Re: INFO: task rcu_gp:3 blocked for more than 122 seconds.

From: Paul E. McKenney
Date: Thu Sep 29 2022 - 11:40:32 EST

Next message: Luck, Tony: "RE: [PATCH] x86/split_lock: Restore warn mode (and add a new one) to avoid userspace regression"
Previous message: Felix Kuehling: "Re: [PATCH] drm/amd/display: fix array-bounds error in dc_stream_remove_writeback()"
In reply to: Borislav Petkov: "INFO: task rcu_gp:3 blocked for more than 122 seconds."
Next in thread: Borislav Petkov: "Re: INFO: task rcu_gp:3 blocked for more than 122 seconds."
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Thu, Sep 29, 2022 at 11:26:35AM +0200, Borislav Petkov wrote:
> Hi Paul,
>
> Mr. Z says I should show this to you.
>
> It is latest Linus + latest tip/master. Happens at boot on one of my
> test boxes.

As discussed on IRC, I got nuttin' on this one. Looks like an RCU
expedited grace period is stuck waiting for its workqueue kthread, and
that this workqueue kthread is stuck for some reason.

Thanx, Paul

> [ 249.149378] INFO: task rcu_gp:3 blocked for more than 122 seconds.
> [ 249.155726] Not tainted 6.0.0-rc7+ #1
> [ 249.160025] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.168000] task:rcu_gp state:I stack:0 pid:3 ppid:2 flags:0x00004000
> [ 249.176483] Call Trace:
> [ 249.178997] <TASK>
> [ 249.181171] __schedule+0x38f/0x1490
> [ 249.184864] schedule+0x5d/0xe0
> [ 249.188086] rescuer_thread+0x2f8/0x390
> [ 249.192044] ? worker_thread+0x3f0/0x3f0
> [ 249.196043] kthread+0xe6/0x110
> [ 249.199282] ? kthread_complete_and_exit+0x20/0x20
> [ 249.204179] ret_from_fork+0x22/0x30
> [ 249.207914] </TASK>
> [ 249.210157] INFO: task rcu_par_gp:4 blocked for more than 122 seconds.
> [ 249.216785] Not tainted 6.0.0-rc7+ #1
> [ 249.221040] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.228974] task:rcu_par_gp state:I stack:0 pid:4 ppid:2 flags:0x00004000
> [ 249.237449] Workqueue: 0x0 (rcu_par_gp)
> [ 249.241437] Call Trace:
> [ 249.243944] <TASK>
> [ 249.246099] __schedule+0x38f/0x1490
> [ 249.249743] schedule+0x5d/0xe0
> [ 249.252941] rescuer_thread+0x2f8/0x390
> [ 249.256831] ? worker_thread+0x3f0/0x3f0
> [ 249.260811] kthread+0xe6/0x110
> [ 249.263997] ? kthread_complete_and_exit+0x20/0x20
> [ 249.268836] ret_from_fork+0x22/0x30
> [ 249.272482] </TASK>
> [ 249.274699] INFO: task slub_flushwq:5 blocked for more than 123 seconds.
> [ 249.281463] Not tainted 6.0.0-rc7+ #1
> [ 249.285692] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.293596] task:slub_flushwq state:I stack:0 pid:5 ppid:2 flags:0x00004000
> [ 249.302039] Call Trace:
> [ 249.304535] <TASK>
> [ 249.306669] __schedule+0x38f/0x1490
> [ 249.310314] schedule+0x5d/0xe0
> [ 249.313496] rescuer_thread+0x2f8/0x390
> [ 249.317388] ? worker_thread+0x3f0/0x3f0
> [ 249.321355] kthread+0xe6/0x110
> [ 249.324536] ? kthread_complete_and_exit+0x20/0x20
> [ 249.329380] ret_from_fork+0x22/0x30
> [ 249.333019] </TASK>
> [ 249.335236] INFO: task kworker/0:0:6 blocked for more than 123 seconds.
> [ 249.341926] Not tainted 6.0.0-rc7+ #1
> [ 249.346157] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.354062] task:kworker/0:0 state:I stack:0 pid:6 ppid:2 flags:0x00004000
> [ 249.362506] Workqueue: 0x0 (rcu_par_gp)
> [ 249.366471] Call Trace:
> [ 249.368953] <TASK>
> [ 249.371087] __schedule+0x38f/0x1490
> [ 249.374724] schedule+0x5d/0xe0
> [ 249.377897] worker_thread+0xbc/0x3f0
> [ 249.381599] ? process_one_work+0x580/0x580
> [ 249.385821] kthread+0xe6/0x110
> [ 249.389009] ? kthread_complete_and_exit+0x20/0x20
> [ 249.393851] ret_from_fork+0x22/0x30
> [ 249.397489] </TASK>
> [ 249.399713] INFO: task kworker/0:0H:7 blocked for more than 123 seconds.
> [ 249.406479] Not tainted 6.0.0-rc7+ #1
> [ 249.410710] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.418614] task:kworker/0:0H state:I stack:0 pid:7 ppid:2 flags:0x00004000
> [ 249.427053] Workqueue: 0x0 (events_highpri)
> [ 249.431608] Call Trace:
> [ 249.434336] <TASK>
> [ 249.436697] __schedule+0x38f/0x1490
> [ 249.440554] schedule+0x5d/0xe0
> [ 249.443952] worker_thread+0xbc/0x3f0
> [ 249.447877] ? process_one_work+0x580/0x580
> [ 249.452317] kthread+0xe6/0x110
> [ 249.455716] ? kthread_complete_and_exit+0x20/0x20
> [ 249.460779] ret_from_fork+0x22/0x30
> [ 249.464632] </TASK>
> [ 249.467064] INFO: task kworker/u64:0:8 blocked for more than 123 seconds.
> [ 249.474146] Not tainted 6.0.0-rc7+ #1
> [ 249.478601] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.486736] task:kworker/u64:0 state:I stack:0 pid:8 ppid:2 flags:0x00004000
> [ 249.495407] Workqueue: 0x0 (scsi_tmf_1)
> [ 249.499603] Call Trace:
> [ 249.502340] <TASK>
> [ 249.504699] __schedule+0x38f/0x1490
> [ 249.508556] schedule+0x5d/0xe0
> [ 249.511951] worker_thread+0xbc/0x3f0
> [ 249.515876] ? process_one_work+0x580/0x580
> [ 249.520321] kthread+0xe6/0x110
> [ 249.523719] ? kthread_complete_and_exit+0x20/0x20
> [ 249.528781] ret_from_fork+0x22/0x30
> [ 249.532636] </TASK>
> [ 249.535080] INFO: task kworker/0:1H:9 blocked for more than 123 seconds.
> [ 249.542069] Not tainted 6.0.0-rc7+ #1
> [ 249.546527] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.554665] task:kworker/0:1H state:I stack:0 pid:9 ppid:2 flags:0x00004000
> [ 249.563331] Workqueue: 0x0 (kblockd)
> [ 249.567268] Call Trace:
> [ 249.569989] <TASK>
> [ 249.572348] __schedule+0x38f/0x1490
> [ 249.576205] schedule+0x5d/0xe0
> [ 249.579607] worker_thread+0xbc/0x3f0
> [ 249.583535] ? process_one_work+0x580/0x580
> [ 249.587975] kthread+0xe6/0x110
> [ 249.591371] ? kthread_complete_and_exit+0x20/0x20
> [ 249.596430] ret_from_fork+0x22/0x30
> [ 249.600289] </TASK>
> [ 249.602726] INFO: task mm_percpu_wq:10 blocked for more than 123 seconds.
> [ 249.609811] Not tainted 6.0.0-rc7+ #1
> [ 249.614262] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.622398] task:mm_percpu_wq state:I stack:0 pid:10 ppid:2 flags:0x00004000
> [ 249.631063] Call Trace:
> [ 249.633781] <TASK>
> [ 249.636142] __schedule+0x38f/0x1490
> [ 249.640006] schedule+0x5d/0xe0
> [ 249.643419] rescuer_thread+0x2f8/0x390
> [ 249.647524] ? worker_thread+0x3f0/0x3f0
> [ 249.651703] kthread+0xe6/0x110
> [ 249.655105] ? kthread_complete_and_exit+0x20/0x20
> [ 249.660167] ret_from_fork+0x22/0x30
> [ 249.664033] </TASK>
> [ 249.666489] INFO: task rcu_tasks_kthre:11 blocked for more than 123 seconds.
> [ 249.673828] Not tainted 6.0.0-rc7+ #1
> [ 249.678277] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.686413] task:rcu_tasks_kthre state:I stack:0 pid:11 ppid:2 flags:0x00004000
> [ 249.695068] Call Trace:
> [ 249.697802] <TASK>
> [ 249.700161] __schedule+0x38f/0x1490
> [ 249.704020] ? mark_held_locks+0x49/0x80
> [ 249.708229] ? rcu_tasks_one_gp+0x3e0/0x3e0
> [ 249.712728] schedule+0x5d/0xe0
> [ 249.716133] rcu_tasks_one_gp+0x19e/0x3e0
> [ 249.720428] ? rcu_tasks_one_gp+0x3e0/0x3e0
> [ 249.724879] rcu_tasks_kthread+0x31/0x40
> [ 249.729072] kthread+0xe6/0x110
> [ 249.732482] ? kthread_complete_and_exit+0x20/0x20
> [ 249.737565] ret_from_fork+0x22/0x30
> [ 249.741429] </TASK>
> [ 249.743865] INFO: task rcu_tasks_rude_:12 blocked for more than 123 seconds.
> [ 249.751224] Not tainted 6.0.0-rc7+ #1
> [ 249.755698] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 249.763861] task:rcu_tasks_rude_ state:I stack:0 pid:12 ppid:2 flags:0x00004000
> [ 249.772515] Call Trace:
> [ 249.775256] <TASK>
> [ 249.777629] __schedule+0x38f/0x1490
> [ 249.781482] ? mark_held_locks+0x49/0x80
> [ 249.785667] ? rcu_tasks_one_gp+0x3e0/0x3e0
> [ 249.790148] schedule+0x5d/0xe0
> [ 249.793559] rcu_tasks_one_gp+0x19e/0x3e0
> [ 249.797866] ? rcu_tasks_one_gp+0x3e0/0x3e0
> [ 249.802315] rcu_tasks_kthread+0x31/0x40
> [ 249.806515] kthread+0xe6/0x110
> [ 249.809945] ? kthread_complete_and_exit+0x20/0x20
> [ 249.815007] ret_from_fork+0x22/0x30
> [ 249.818904] </TASK>
> [ 249.821366]
> Showing all locks held in the system:
> [ 249.828044] 1 lock held by rcu_tasks_kthre/11:
> [ 249.832767] #0: ffffffff8273bdf0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x2b/0x3e0
> [ 249.842684] 1 lock held by rcu_tasks_rude_/12:
> [ 249.847389] #0: ffffffff8273bb70 (rcu_tasks_rude.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x2b/0x3e0
> [ 249.857732] 1 lock held by khungtaskd/56:
> [ 249.862000] #0: ffffffff8273c800 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x15/0x16b
> [ 249.871288] 1 lock held by in:imklog/1289:
> [ 249.875633] #0: ffff888100f309a8 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0x65/0xb0
>
> [ 249.885886] =============================================
>
>
> --
> Regards/Gruss,
> Boris.
>
> https://people.kernel.org/tglx/notes-about-netiquette

Next message: Luck, Tony: "RE: [PATCH] x86/split_lock: Restore warn mode (and add a new one) to avoid userspace regression"
Previous message: Felix Kuehling: "Re: [PATCH] drm/amd/display: fix array-bounds error in dc_stream_remove_writeback()"
In reply to: Borislav Petkov: "INFO: task rcu_gp:3 blocked for more than 122 seconds."
Next in thread: Borislav Petkov: "Re: INFO: task rcu_gp:3 blocked for more than 122 seconds."
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]