* Re: workqueue lockup debug
2024-10-24 15:49 workqueue lockup debug John Garry
@ 2024-10-24 18:56 ` Tejun Heo
2024-10-25 9:28 ` John Garry
2024-10-29 4:11 ` Dave Chinner
2024-11-07 12:39 ` Thorsten Leemhuis
2 siblings, 1 reply; 11+ messages in thread
From: Tejun Heo @ 2024-10-24 18:56 UTC (permalink / raw)
To: John Garry
Cc: jiangshanlai, mingo, peterz, juri.lelli, jack, david, akpm,
linux-kernel
Hey, John.
On Thu, Oct 24, 2024 at 04:49:40PM +0100, John Garry wrote:
> Hi workqueue and scheduler maintainers,
>
> As reported in https://lore.kernel.org/linux-fsdevel/df9db1ce-17d9-49f1-ab6d-7ed9a4f1f9c0@oracle.com/T/#m506b9edb1340cdddd87c6d14d20222ca8d7e8796,
> I am experiencing a workqueue lockup for v6.12-rcX.
>
> At the point it occurs, the system becomes unresponsive and I cannot bring
> it back to life.
>
> Enabling /proc/sys/kernel/softlockup_all_cpu_backtrace does not give
> anything extra in the way of debug. All I get is something like this:
>
> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221 at
> Oct 24 15:34:02 ...
> kernel:watchdog: BUG: soft lockup - CPU#29 stuck for 22s! [mysqld:14352]
>
> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221 at
> Oct 24 15:34:02 ...
> kernel:BUG: workqueue lockup - pool cpus=4 node=0 flags=0x0 nice=0 stuck
> for 30s!
>
> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221 at
> Oct 24 15:34:02 ...
> kernel:BUG: workqueue lockup - pool cpus=31 node=0 flags=0x0 nice=0 stuck
> for 49s!
> ^C
>
> Can you advise on a robust method to get some debug from this system?
>
> Maybe this is a scheduler issue, as Dave mentioned in that same thread.
So, while the symptom *could* be a workqueue bug, wq lockups are usually
more a side-effect of some other problem. All that wq is saying is that some
work item hasn't made forward progress for too long. Given that there are
soft lockup messages, which can't be caused by wq lockups but can definitely
trigger wq lockups, I'd start with debugging what's happening with the CPU
that triggered soft lockup. Soft lockups are nice in that they're
synchronous failures, so probably start with the backtrace?
Thanks.
--
tejun
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: workqueue lockup debug
2024-10-24 18:56 ` Tejun Heo
@ 2024-10-25 9:28 ` John Garry
0 siblings, 0 replies; 11+ messages in thread
From: John Garry @ 2024-10-25 9:28 UTC (permalink / raw)
To: Tejun Heo
Cc: jiangshanlai, mingo, peterz, juri.lelli, jack, david, akpm,
linux-kernel
On 24/10/2024 19:56, Tejun Heo wrote:
Hi Tejun,
>
> On Thu, Oct 24, 2024 at 04:49:40PM +0100, John Garry wrote:
>> Hi workqueue and scheduler maintainers,
>>
>> As reported in https://urldefense.com/v3/__https://lore.kernel.org/linux-fsdevel/df9db1ce-17d9-49f1-ab6d-7ed9a4f1f9c0@oracle.com/T/*m506b9edb1340cdddd87c6d14d20222ca8d7e8796__;Iw!!ACWV5N9M2RV99hQ!Jn5gFi_KIzLb-7uCOvHRIcf9Zd4RyHCTnm15Lo8u0KsgaMmwEPZHH2m4l-w4Fr-b6aRICoRWb5DU$ ,
>> I am experiencing a workqueue lockup for v6.12-rcX.
>>
>> At the point it occurs, the system becomes unresponsive and I cannot bring
>> it back to life.
>>
>> Enabling /proc/sys/kernel/softlockup_all_cpu_backtrace does not give
>> anything extra in the way of debug. All I get is something like this:
>>
>> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221 at
>> Oct 24 15:34:02 ...
>> kernel:watchdog: BUG: soft lockup - CPU#29 stuck for 22s! [mysqld:14352]
>>
>> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221 at
>> Oct 24 15:34:02 ...
>> kernel:BUG: workqueue lockup - pool cpus=4 node=0 flags=0x0 nice=0 stuck
>> for 30s!
>>
>> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221 at
>> Oct 24 15:34:02 ...
>> kernel:BUG: workqueue lockup - pool cpus=31 node=0 flags=0x0 nice=0 stuck
>> for 49s!
>> ^C
>>
>> Can you advise on a robust method to get some debug from this system?
>>
>> Maybe this is a scheduler issue, as Dave mentioned in that same thread.
>
> So, while the symptom *could* be a workqueue bug, wq lockups are usually
> more a side-effect of some other problem.
Sure
> All that wq is saying is that some
> work item hasn't made forward progress for too long. Given that there are
> soft lockup messages, which can't be caused by wq lockups but can definitely
> trigger wq lockups, I'd start with debugging what's happening with the CPU
> that triggered soft lockup.
ok
> Soft lockups are nice in that they're
> synchronous failures, so probably start with the backtrace?
>
I'm not getting any backtrace, which is not helping the issue.
But I'll continue to look.
Thanks,
John
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: workqueue lockup debug
2024-10-24 15:49 workqueue lockup debug John Garry
2024-10-24 18:56 ` Tejun Heo
@ 2024-10-29 4:11 ` Dave Chinner
2024-10-29 8:07 ` John Garry
2024-11-07 12:39 ` Thorsten Leemhuis
2 siblings, 1 reply; 11+ messages in thread
From: Dave Chinner @ 2024-10-29 4:11 UTC (permalink / raw)
To: John Garry
Cc: tj, jiangshanlai, mingo, peterz, juri.lelli, jack, akpm,
linux-kernel
On Thu, Oct 24, 2024 at 04:49:40PM +0100, John Garry wrote:
> Hi workqueue and scheduler maintainers,
>
> As reported in https://lore.kernel.org/linux-fsdevel/df9db1ce-17d9-49f1-ab6d-7ed9a4f1f9c0@oracle.com/T/#m506b9edb1340cdddd87c6d14d20222ca8d7e8796,
> I am experiencing a workqueue lockup for v6.12-rcX.
>
> At the point it occurs, the system becomes unresponsive and I cannot bring
> it back to life.
>
> Enabling /proc/sys/kernel/softlockup_all_cpu_backtrace does not give
> anything extra in the way of debug. All I get is something like this:
>
> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221 at
> Oct 24 15:34:02 ...
> kernel:watchdog: BUG: soft lockup - CPU#29 stuck for 22s! [mysqld:14352]
>
> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221 at
> Oct 24 15:34:02 ...
> kernel:BUG: workqueue lockup - pool cpus=4 node=0 flags=0x0 nice=0 stuck
> for 30s!
>
> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221 at
> Oct 24 15:34:02 ...
> kernel:BUG: workqueue lockup - pool cpus=31 node=0 flags=0x0 nice=0 stuck
> for 49s!
> ^C
>
> Can you advise on a robust method to get some debug from this system?
>
> Maybe this is a scheduler issue, as Dave mentioned in that same thread.
I just got a new hit on the scheduler issue on 6.12-rc5:
[ 172.477662] ------------[ cut here ]------------
[ 172.480660] se->on_rq
[ 172.480682] WARNING: CPU: 3 PID: 728318 at kernel/sched/fair.c:5629 pick_task_fair+0xb6/0x1b0
[ 172.487172] Modules linked in:
[ 172.488911] CPU: 3 UID: 0 PID: 728318 Comm: 291 Not tainted 6.12.0-rc5-dgc+ #273
[ 172.492022] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.3-debian-1.16.3-2 04/01/2014
[ 172.496029] RIP: 0010:pick_task_fair+0xb6/0x1b0
[ 172.497978] Code: 40 f3 f3 03 01 74 2a 41 80 7f 50 00 74 96 f6 05 31 f3 f3 03 01 75 8d c6 05 28 f3 f3 03 01 48 c7 c7 41 26 e4 82 e8 7a d7 fa ff <0f> 0b e9 73 ff ff ff c6 05 0d f3 f3 03 01 48 c7 c7 2f 26 e4 82 e8
[ 172.505868] RSP: 0018:ffffc9002ec83d60 EFLAGS: 00010046
[ 172.508111] RAX: bdcdd05ee831a400 RBX: 0000000000000000 RCX: 0000000000000027
[ 172.511139] RDX: 0000000000000000 RSI: 00000000ffdfffff RDI: ffff88881fadc9c8
[ 172.514326] RBP: ffffc9002ec83d88 R08: 00000000001fffff R09: ffff88a018a00000
[ 172.517804] R10: 00000000005ffffd R11: 0000000000000004 R12: ffff888122b58c00
[ 172.520788] R13: ffff88881faf0140 R14: ffff88881faf00c0 R15: ffff88819e8cd180
[ 172.523748] FS: 0000000000000000(0000) GS:ffff88881fac0000(0000) knlGS:0000000000000000
[ 172.527167] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 172.529571] CR2: 00007f378e8866fc CR3: 000000104daae000 CR4: 0000000000350ef0
[ 172.532601] Call Trace:
[ 172.533666] <TASK>
[ 172.534557] ? show_regs+0x5e/0x70
[ 172.535993] ? __warn+0xd0/0x1d0
[ 172.537430] ? pick_task_fair+0xb6/0x1b0
[ 172.539062] ? report_bug+0x145/0x1f0
[ 172.540619] ? handle_bug+0x67/0x90
[ 172.542060] ? exc_invalid_op+0x1b/0x50
[ 172.543854] ? asm_exc_invalid_op+0x1b/0x20
[ 172.545688] ? pick_task_fair+0xb6/0x1b0
[ 172.547353] pick_next_task_fair+0x27/0x330
[ 172.549090] __schedule+0x2ad/0xb10
[ 172.550460] do_task_dead+0x43/0x50
[ 172.551743] do_exit+0x836/0xab0
[ 172.552950] do_group_exit+0x8f/0x90
[ 172.554274] __x64_sys_exit_group+0x17/0x20
[ 172.555808] x64_sys_call+0x2ed3/0x2ee0
[ 172.557210] do_syscall_64+0x68/0x130
[ 172.558531] ? exc_page_fault+0x62/0xc0
[ 172.559907] entry_SYSCALL_64_after_hwframe+0x76/0x7e
[ 172.561739] RIP: 0033:0x7f378e74b3c5
[ 172.563036] Code: Unable to access opcode bytes at 0x7f378e74b39b.
[ 172.565278] RSP: 002b:00007ffd21861488 EFLAGS: 00000206 ORIG_RAX: 00000000000000e7
[ 172.568001] RAX: ffffffffffffffda RBX: 00007f378e857fa8 RCX: 00007f378e74b3c5
[ 172.570589] RDX: 00000000000000e7 RSI: ffffffffffffff88 RDI: 0000000000000000
[ 172.573182] RBP: 0000000000000000 R08: 00007ffd21861428 R09: 00007ffd218613af
[ 172.575758] R10: 00007ffd21861320 R11: 0000000000000206 R12: 00007f378e856680
[ 172.578356] R13: 00007f378e8b9f40 R14: 0000000000000001 R15: 00007f378e857fc0
[ 172.580941] </TASK>
There was nothing particularly obvious that caused it. It's a 64p
VM, running a heavy concurrent fstests workload that takes about 20
minutes to complete. There are a bit over 8000 tasks reported, most
of them kernel threads. The load is consuming about 50 CPUs, 40GB of
RAM, sustaining ~3GB/s of IO to/from disk across about 130 block
devices and the scheduler is context switching around 800,000 times
a second.
I have no idea how to reproduce this on demand - it randomly shows
up in about 1 in every 10 test runs and all the tests running at
that point in time report failure because they all detect this
warning in dmesg.
-Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: workqueue lockup debug
2024-10-29 4:11 ` Dave Chinner
@ 2024-10-29 8:07 ` John Garry
2024-10-29 15:51 ` John Garry
0 siblings, 1 reply; 11+ messages in thread
From: John Garry @ 2024-10-29 8:07 UTC (permalink / raw)
To: Dave Chinner
Cc: tj, jiangshanlai, mingo, peterz, juri.lelli, jack, akpm,
linux-kernel
On 29/10/2024 04:11, Dave Chinner wrote:
>> Can you advise on a robust method to get some debug from this system?
>>
>> Maybe this is a scheduler issue, as Dave mentioned in that same thread.
> I just got a new hit on the scheduler issue on 6.12-rc5:
>
> [ 172.477662] ------------[ cut here ]------------
> [ 172.480660] se->on_rq
> [ 172.480682] WARNING: CPU: 3 PID: 728318 at kernel/sched/fair.c:5629 pick_task_fair+0xb6/0x1b0
> [ 172.487172] Modules linked in:
> [ 172.488911] CPU: 3 UID: 0 PID: 728318 Comm: 291 Not tainted 6.12.0-rc5-dgc+ #273
> [ 172.492022] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.3-debian-1.16.3-2 04/01/2014
> [ 172.496029] RIP: 0010:pick_task_fair+0xb6/0x1b0
> [ 172.497978] Code: 40 f3 f3 03 01 74 2a 41 80 7f 50 00 74 96 f6 05 31 f3 f3 03 01 75 8d c6 05 28 f3 f3 03 01 48 c7 c7 41 26 e4 82 e8 7a d7 fa ff <0f> 0b e9 73 ff ff ff c6 05 0d f3 f3 03 01 48 c7 c7 2f 26 e4 82 e8
> [ 172.505868] RSP: 0018:ffffc9002ec83d60 EFLAGS: 00010046
> [ 172.508111] RAX: bdcdd05ee831a400 RBX: 0000000000000000 RCX: 0000000000000027
> [ 172.511139] RDX: 0000000000000000 RSI: 00000000ffdfffff RDI: ffff88881fadc9c8
> [ 172.514326] RBP: ffffc9002ec83d88 R08: 00000000001fffff R09: ffff88a018a00000
> [ 172.517804] R10: 00000000005ffffd R11: 0000000000000004 R12: ffff888122b58c00
> [ 172.520788] R13: ffff88881faf0140 R14: ffff88881faf00c0 R15: ffff88819e8cd180
> [ 172.523748] FS: 0000000000000000(0000) GS:ffff88881fac0000(0000) knlGS:0000000000000000
> [ 172.527167] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 172.529571] CR2: 00007f378e8866fc CR3: 000000104daae000 CR4: 0000000000350ef0
> [ 172.532601] Call Trace:
> [ 172.533666] <TASK>
> [ 172.534557] ? show_regs+0x5e/0x70
> [ 172.535993] ? __warn+0xd0/0x1d0
> [ 172.537430] ? pick_task_fair+0xb6/0x1b0
> [ 172.539062] ? report_bug+0x145/0x1f0
> [ 172.540619] ? handle_bug+0x67/0x90
> [ 172.542060] ? exc_invalid_op+0x1b/0x50
> [ 172.543854] ? asm_exc_invalid_op+0x1b/0x20
> [ 172.545688] ? pick_task_fair+0xb6/0x1b0
> [ 172.547353] pick_next_task_fair+0x27/0x330
> [ 172.549090] __schedule+0x2ad/0xb10
> [ 172.550460] do_task_dead+0x43/0x50
> [ 172.551743] do_exit+0x836/0xab0
> [ 172.552950] do_group_exit+0x8f/0x90
> [ 172.554274] __x64_sys_exit_group+0x17/0x20
> [ 172.555808] x64_sys_call+0x2ed3/0x2ee0
> [ 172.557210] do_syscall_64+0x68/0x130
> [ 172.558531] ? exc_page_fault+0x62/0xc0
> [ 172.559907] entry_SYSCALL_64_after_hwframe+0x76/0x7e
> [ 172.561739] RIP: 0033:0x7f378e74b3c5
> [ 172.563036] Code: Unable to access opcode bytes at 0x7f378e74b39b.
> [ 172.565278] RSP: 002b:00007ffd21861488 EFLAGS: 00000206 ORIG_RAX: 00000000000000e7
> [ 172.568001] RAX: ffffffffffffffda RBX: 00007f378e857fa8 RCX: 00007f378e74b3c5
> [ 172.570589] RDX: 00000000000000e7 RSI: ffffffffffffff88 RDI: 0000000000000000
> [ 172.573182] RBP: 0000000000000000 R08: 00007ffd21861428 R09: 00007ffd218613af
> [ 172.575758] R10: 00007ffd21861320 R11: 0000000000000206 R12: 00007f378e856680
> [ 172.578356] R13: 00007f378e8b9f40 R14: 0000000000000001 R15: 00007f378e857fc0
> [ 172.580941] </TASK>
>
> There was nothing particularly obvious that caused it. It's a 64p
> VM, running a heavy concurrent fstests workload that takes about 20
> minutes to complete. There are a bit over 8000 tasks reported, most
> of them kernel threads. The load is consuming about 50 CPUs, 40GB of
> RAM, sustaining ~3GB/s of IO to/from disk across about 130 block
> devices and the scheduler is context switching around 800,000 times
> a second.
>
> I have no idea how to reproduce this on demand - it randomly shows
> up in about 1 in every 10 test runs and all the tests running at
> that point in time report failure because they all detect this
> warning in dmesg.
I have not been able to test v6.12-rc5 yet.
Can you share your config? And/Or compare to mine at
https://pastebin.com/Y7DXnMG2
Maybe we can see what was merged for the sched in 6.12, and I can try
before and after. I don't like the prospect of a full bisect.
Thanks,
John
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: workqueue lockup debug
2024-10-29 8:07 ` John Garry
@ 2024-10-29 15:51 ` John Garry
0 siblings, 0 replies; 11+ messages in thread
From: John Garry @ 2024-10-29 15:51 UTC (permalink / raw)
To: Dave Chinner
Cc: tj, jiangshanlai, mingo, peterz, juri.lelli, jack, akpm,
linux-kernel, chandan.babu
On 29/10/2024 08:07, John Garry wrote:
+ Chandan
Note that Chandan also reported this other issue
https://lore.kernel.org/all/87r08zvsdd.fsf@debian-BULLSEYE-live-builder-AMD64/,
which still exists in rc4
>>> Maybe this is a scheduler issue, as Dave mentioned in that same thread.
>> I just got a new hit on the scheduler issue on 6.12-rc5:
>>
>> [ 172.477662] ------------[ cut here ]------------
>> [ 172.480660] se->on_rq
>> [ 172.480682] WARNING: CPU: 3 PID: 728318 at kernel/sched/fair.c:5629
That WARN is new code in 6.12
>> pick_task_fair+0xb6/0x1b0
>> [ 172.487172] Modules linked in:
>> [ 172.488911] CPU: 3 UID: 0 PID: 728318 Comm: 291 Not tainted 6.12.0-
>> rc5-dgc+ #273
>> [ 172.492022] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
>> BIOS 1.16.3-debian-1.16.3-2 04/01/2014
>> [ 172.496029] RIP: 0010:pick_task_fair+0xb6/0x1b0
>> [ 172.497978] Code: 40 f3 f3 03 01 74 2a 41 80 7f 50 00 74 96 f6 05
>> 31 f3 f3 03 01 75 8d c6 05 28 f3 f3 03 01 48 c7 c7 41 26 e4 82 e8 7a
>> d7 fa ff <0f> 0b e9 73 ff ff ff c6 05 0d f3 f3 03 01 48 c7 c7 2f 26 e4
>> 82 e8
>> [ 172.505868] RSP: 0018:ffffc9002ec83d60 EFLAGS: 00010046
>> [ 172.508111] RAX: bdcdd05ee831a400 RBX: 0000000000000000 RCX:
>> 0000000000000027
>> [ 172.511139] RDX: 0000000000000000 RSI: 00000000ffdfffff RDI:
>> ffff88881fadc9c8
>> [ 172.514326] RBP: ffffc9002ec83d88 R08: 00000000001fffff R09:
>> ffff88a018a00000
>> [ 172.517804] R10: 00000000005ffffd R11: 0000000000000004 R12:
>> ffff888122b58c00
>> [ 172.520788] R13: ffff88881faf0140 R14: ffff88881faf00c0 R15:
>> ffff88819e8cd180
>> [ 172.523748] FS: 0000000000000000(0000) GS:ffff88881fac0000(0000)
>> knlGS:0000000000000000
>> [ 172.527167] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 172.529571] CR2: 00007f378e8866fc CR3: 000000104daae000 CR4:
>> 0000000000350ef0
>> [ 172.532601] Call Trace:
>> [ 172.533666] <TASK>
>> [ 172.534557] ? show_regs+0x5e/0x70
>> [ 172.535993] ? __warn+0xd0/0x1d0
>> [ 172.537430] ? pick_task_fair+0xb6/0x1b0
>> [ 172.539062] ? report_bug+0x145/0x1f0
>> [ 172.540619] ? handle_bug+0x67/0x90
>> [ 172.542060] ? exc_invalid_op+0x1b/0x50
>> [ 172.543854] ? asm_exc_invalid_op+0x1b/0x20
>> [ 172.545688] ? pick_task_fair+0xb6/0x1b0
>> [ 172.547353] pick_next_task_fair+0x27/0x330
>> [ 172.549090] __schedule+0x2ad/0xb10
>> [ 172.550460] do_task_dead+0x43/0x50
>> [ 172.551743] do_exit+0x836/0xab0
>> [ 172.552950] do_group_exit+0x8f/0x90
>> [ 172.554274] __x64_sys_exit_group+0x17/0x20
>> [ 172.555808] x64_sys_call+0x2ed3/0x2ee0
>> [ 172.557210] do_syscall_64+0x68/0x130
>> [ 172.558531] ? exc_page_fault+0x62/0xc0
>> [ 172.559907] entry_SYSCALL_64_after_hwframe+0x76/0x7e
>> [ 172.561739] RIP: 0033:0x7f378e74b3c5
>> [ 172.563036] Code: Unable to access opcode bytes at 0x7f378e74b39b.
>> [ 172.565278] RSP: 002b:00007ffd21861488 EFLAGS: 00000206 ORIG_RAX:
>> 00000000000000e7
>> [ 172.568001] RAX: ffffffffffffffda RBX: 00007f378e857fa8 RCX:
>> 00007f378e74b3c5
>> [ 172.570589] RDX: 00000000000000e7 RSI: ffffffffffffff88 RDI:
>> 0000000000000000
>> [ 172.573182] RBP: 0000000000000000 R08: 00007ffd21861428 R09:
>> 00007ffd218613af
>> [ 172.575758] R10: 00007ffd21861320 R11: 0000000000000206 R12:
>> 00007f378e856680
>> [ 172.578356] R13: 00007f378e8b9f40 R14: 0000000000000001 R15:
>> 00007f378e857fc0
>> [ 172.580941] </TASK>
>>
>> There was nothing particularly obvious that caused it. It's a 64p
>> VM, running a heavy concurrent fstests workload that takes about 20
>> minutes to complete. There are a bit over 8000 tasks reported, most
>> of them kernel threads. The load is consuming about 50 CPUs, 40GB of
>> RAM, sustaining ~3GB/s of IO to/from disk across about 130 block
>> devices and the scheduler is context switching around 800,000 times
>> a second.
>>
>> I have no idea how to reproduce this on demand - it randomly shows
>> up in about 1 in every 10 test runs and all the tests running at
>> that point in time report failure because they all detect this
>> warning in dmesg.
>
> I have not been able to test v6.12-rc5 yet.
Just to confirm, v6.12-rc5 also hangs for me
>
> Can you share your config? And/Or compare to mine at https://
> pastebin.com/Y7DXnMG2
>
> Maybe we can see what was merged for the sched in 6.12, and I can try
> before and after. I don't like the prospect of a full bisect.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: workqueue lockup debug
2024-10-24 15:49 workqueue lockup debug John Garry
2024-10-24 18:56 ` Tejun Heo
2024-10-29 4:11 ` Dave Chinner
@ 2024-11-07 12:39 ` Thorsten Leemhuis
2024-11-07 22:57 ` Dave Chinner
2 siblings, 1 reply; 11+ messages in thread
From: Thorsten Leemhuis @ 2024-11-07 12:39 UTC (permalink / raw)
To: John Garry, tj, jiangshanlai, mingo, peterz, juri.lelli
Cc: jack, david, akpm, linux-kernel
On 24.10.24 17:49, John Garry wrote:
> Hi workqueue and scheduler maintainers,
>
> As reported in https://lore.kernel.org/linux-fsdevel/df9db1ce-17d9-49f1-
> ab6d-7ed9a4f1f9c0@oracle.com/T/
> #m506b9edb1340cdddd87c6d14d20222ca8d7e8796, I am experiencing a
> workqueue lockup for v6.12-rcX.
John, what this resolved in between? This and the other thread[1] look
stalled, but I might be missing something. Asking, because I have this
on my list of tracked regressions and wonder if this is something that
better should be solved one way or another before 6.12.
[1]
https://lore.kernel.org/lkml/63d6ceeb-a22f-4dee-bc9d-8687ce4c7355@oracle.com/
Ciao, Thorsten
> At the point it occurs, the system becomes unresponsive and I cannot
> bring it back to life.
>
> Enabling /proc/sys/kernel/softlockup_all_cpu_backtrace does not give
> anything extra in the way of debug. All I get is something like this:
>
> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221
> at Oct 24 15:34:02 ...
> kernel:watchdog: BUG: soft lockup - CPU#29 stuck for 22s! [mysqld:14352]
>
> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221
> at Oct 24 15:34:02 ...
> kernel:BUG: workqueue lockup - pool cpus=4 node=0 flags=0x0 nice=0
> stuck for 30s!
>
> Message from syslogd@jgarry-atomic-write-exp-e4-8-instance-20231214-1221
> at Oct 24 15:34:02 ...
> kernel:BUG: workqueue lockup - pool cpus=31 node=0 flags=0x0 nice=0
> stuck for 49s!
> ^C
>
> Can you advise on a robust method to get some debug from this system?
>
> Maybe this is a scheduler issue, as Dave mentioned in that same thread.
>
> Thanks,
> John
>
#regzbot poke
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: workqueue lockup debug
2024-11-07 12:39 ` Thorsten Leemhuis
@ 2024-11-07 22:57 ` Dave Chinner
2024-11-08 8:54 ` Peter Zijlstra
0 siblings, 1 reply; 11+ messages in thread
From: Dave Chinner @ 2024-11-07 22:57 UTC (permalink / raw)
To: Thorsten Leemhuis
Cc: John Garry, tj, jiangshanlai, mingo, peterz, juri.lelli, jack,
akpm, linux-kernel
On Thu, Nov 07, 2024 at 01:39:39PM +0100, Thorsten Leemhuis wrote:
> On 24.10.24 17:49, John Garry wrote:
> > Hi workqueue and scheduler maintainers,
> >
> > As reported in https://lore.kernel.org/linux-fsdevel/df9db1ce-17d9-49f1-
> > ab6d-7ed9a4f1f9c0@oracle.com/T/
> > #m506b9edb1340cdddd87c6d14d20222ca8d7e8796, I am experiencing a
> > workqueue lockup for v6.12-rcX.
>
> John, what this resolved in between? This and the other thread[1] look
> stalled, but I might be missing something. Asking, because I have this
> on my list of tracked regressions and wonder if this is something that
> better should be solved one way or another before 6.12.
>
> [1]
> https://lore.kernel.org/lkml/63d6ceeb-a22f-4dee-bc9d-8687ce4c7355@oracle.com/
I'm still seeing the scheduler bug in -rc6.
-Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: workqueue lockup debug
2024-11-07 22:57 ` Dave Chinner
@ 2024-11-08 8:54 ` Peter Zijlstra
2024-11-11 13:22 ` John Garry
2024-11-11 21:01 ` Dave Chinner
0 siblings, 2 replies; 11+ messages in thread
From: Peter Zijlstra @ 2024-11-08 8:54 UTC (permalink / raw)
To: Dave Chinner
Cc: Thorsten Leemhuis, John Garry, tj, jiangshanlai, mingo,
juri.lelli, jack, akpm, linux-kernel
On Fri, Nov 08, 2024 at 09:57:38AM +1100, Dave Chinner wrote:
> On Thu, Nov 07, 2024 at 01:39:39PM +0100, Thorsten Leemhuis wrote:
> > On 24.10.24 17:49, John Garry wrote:
> > > Hi workqueue and scheduler maintainers,
> > >
> > > As reported in https://lore.kernel.org/linux-fsdevel/df9db1ce-17d9-49f1-
> > > ab6d-7ed9a4f1f9c0@oracle.com/T/
> > > #m506b9edb1340cdddd87c6d14d20222ca8d7e8796, I am experiencing a
> > > workqueue lockup for v6.12-rcX.
> >
> > John, what this resolved in between? This and the other thread[1] look
> > stalled, but I might be missing something. Asking, because I have this
> > on my list of tracked regressions and wonder if this is something that
> > better should be solved one way or another before 6.12.
> >
> > [1]
> > https://lore.kernel.org/lkml/63d6ceeb-a22f-4dee-bc9d-8687ce4c7355@oracle.com/
>
> I'm still seeing the scheduler bug in -rc6.
But that WARN you reported earlier isn't there anymore. So what exactly
are you seeing now?
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: workqueue lockup debug
2024-11-08 8:54 ` Peter Zijlstra
@ 2024-11-11 13:22 ` John Garry
2024-11-11 21:01 ` Dave Chinner
1 sibling, 0 replies; 11+ messages in thread
From: John Garry @ 2024-11-11 13:22 UTC (permalink / raw)
To: Peter Zijlstra, Dave Chinner
Cc: Thorsten Leemhuis, tj, jiangshanlai, mingo, juri.lelli, jack,
akpm, linux-kernel
On 08/11/2024 08:54, Peter Zijlstra wrote:
> On Fri, Nov 08, 2024 at 09:57:38AM +1100, Dave Chinner wrote:
>> On Thu, Nov 07, 2024 at 01:39:39PM +0100, Thorsten Leemhuis wrote:
>>> On 24.10.24 17:49, John Garry wrote:
>>>> Hi workqueue and scheduler maintainers,
>>>>
>>>> As reported in https://urldefense.com/v3/__https://lore.kernel.org/linux-fsdevel/df9db1ce-17d9-49f1-__;!!ACWV5N9M2RV99hQ!K-drGDW_XBDuFwUrnEBHKIab7gT2eumqlwIEviGOHbLBedwmMvP_yJGM98ikNAU5uTtes3Ig7Lk40CG3652p$
>>>> ab6d-7ed9a4f1f9c0@oracle.com/T/
>>>> #m506b9edb1340cdddd87c6d14d20222ca8d7e8796, I am experiencing a
>>>> workqueue lockup for v6.12-rcX.
>>>
>>> John, what this resolved in between? This and the other thread[1] look
>>> stalled, but I might be missing something. Asking, because I have this
>>> on my list of tracked regressions and wonder if this is something that
>>> better should be solved one way or another before 6.12.
>>>
>>> [1]
>>> https://urldefense.com/v3/__https://lore.kernel.org/lkml/63d6ceeb-a22f-4dee-bc9d-8687ce4c7355@oracle.com/__;!!ACWV5N9M2RV99hQ!K-drGDW_XBDuFwUrnEBHKIab7gT2eumqlwIEviGOHbLBedwmMvP_yJGM98ikNAU5uTtes3Ig7Lk40NodyRwu$
>>
>> I'm still seeing the scheduler bug in -rc6.
>
> But that WARN you reported earlier isn't there anymore. So what exactly
> are you seeing now?
My problem reported in
https://lore.kernel.org/lkml/63d6ceeb-a22f-4dee-bc9d-8687ce4c7355@oracle.com/
seems to be fixed after rc5. rc6 and rc7 look ok. But I will test more.
Any idea what could be that fix?
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: workqueue lockup debug
2024-11-08 8:54 ` Peter Zijlstra
2024-11-11 13:22 ` John Garry
@ 2024-11-11 21:01 ` Dave Chinner
1 sibling, 0 replies; 11+ messages in thread
From: Dave Chinner @ 2024-11-11 21:01 UTC (permalink / raw)
To: Peter Zijlstra
Cc: Thorsten Leemhuis, John Garry, tj, jiangshanlai, mingo,
juri.lelli, jack, akpm, linux-kernel
On Fri, Nov 08, 2024 at 09:54:19AM +0100, Peter Zijlstra wrote:
> On Fri, Nov 08, 2024 at 09:57:38AM +1100, Dave Chinner wrote:
> > On Thu, Nov 07, 2024 at 01:39:39PM +0100, Thorsten Leemhuis wrote:
> > > On 24.10.24 17:49, John Garry wrote:
> > > > Hi workqueue and scheduler maintainers,
> > > >
> > > > As reported in https://lore.kernel.org/linux-fsdevel/df9db1ce-17d9-49f1-
> > > > ab6d-7ed9a4f1f9c0@oracle.com/T/
> > > > #m506b9edb1340cdddd87c6d14d20222ca8d7e8796, I am experiencing a
> > > > workqueue lockup for v6.12-rcX.
> > >
> > > John, what this resolved in between? This and the other thread[1] look
> > > stalled, but I might be missing something. Asking, because I have this
> > > on my list of tracked regressions and wonder if this is something that
> > > better should be solved one way or another before 6.12.
> > >
> > > [1]
> > > https://lore.kernel.org/lkml/63d6ceeb-a22f-4dee-bc9d-8687ce4c7355@oracle.com/
> >
> > I'm still seeing the scheduler bug in -rc6.
>
> But that WARN you reported earlier isn't there anymore. So what exactly
> are you seeing now?
I just went back and checked the logs. It does appear I was running
an -rc5 base kernel, but that just makes me really confused because
I was running mount path debug trace_printk patches at the time and
that kernel was clearly built on a 6.12-rc6 base.
Yet, apparently, despite getting the tracing output I expected to
see, the kernel still reported as 6.12.0-rc5-dgc+. I suspect some
kind of weird delta rebuild issue (possibly some of my machines have
dropped time sync), but that's my problem to sort out.
IOWs, ignore this, I'll do a full rebuild on -rc7 and test again.
If you don't hear from me again, I haven't hit new problems.
-Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 11+ messages in thread