Created attachment 285799 [details] The repro.c file I ran into this problem with a reproduction file created by a modified version of Syzkaller on a modified version of kernel. The only modification I added is a 20 microsecond delay before rcu_dereference which looks like this: diff a/include/linux/rcupdate.h b/include/linux/rcupdate.h 30a31,33 > #include <asm/delay.h> > > 508c511 < #define rcu_dereference(p) rcu_dereference_check(p, 0) --- > #define rcu_dereference(p) ({ udelay(20); rcu_dereference_check(p, 0); }) The configuration is a default config with kvmconfig and CONFIG_PROVE_LOCKING enabled as well as CONFIG_RCU_CPU_STALL_TIMEOUT=100. Running the compiled repro.c, the first observation is a rcu stall will always appear. But running it for a while it sometimes could trigger the circular locking dependency. You can find the full console output below. I also have no idea whether the rcu stall (see the full log) is a bug or is because of my 10 microsecond delay violates some assumptions of the kernel. The full console output: Debian GNU/Linux 9 test ttyS0 test login: root Unable to get valid context for root Last login: Tue Oct 29 01:16:41 UTC 2019 on ttyS0 Linux test 5.3.7 #2 SMP Tue Oct 29 09:12:36 CST 2019 x86_64 The programs included with the Debian GNU/Linux system are free software; the exact distribution terms for each program are described in the individual files in /usr/share/doc/*/copyright. Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent permitted by applicable law. root@test:~# ls neigh_timer_handler_repro.c root@test:~# gcc neigh_timer_handler_repro.c root@test:~# ./a.out [ 37.110044] hrtimer: interrupt took 57027 ns [ 142.199052] rcu: INFO: rcu_sched self-detected stall on CPU [ 142.202815] rcu: 0-...!: (105000 ticks this GP) idle=e4e/1/0x4000000000000004 soft irq=21700/21700 fqs=0 [ 142.204499] (t=105000 jiffies g=79405 q=2) [ 142.205223] rcu: rcu_sched kthread starved for 105000 jiffies! g79405 f0x0 RCU_GP_WAIT _FQS(5) ->state=0x0 ->cpu=0 [ 142.206976] rcu: RCU grace-period kthread stack dump: [ 142.207860] rcu_sched R running task 30120 10 2 0x80004000 [ 142.209121] Call Trace: [ 142.209570] ? __schedule+0x73f/0x1440 [ 142.210248] ? __sched_text_start+0x8/0x8 [ 142.210943] schedule+0xb7/0x240 [ 142.211510] schedule_timeout+0x3a9/0x9e0 [ 142.212199] ? usleep_range+0x130/0x130 [ 142.212866] ? lockdep_hardirqs_on+0x37f/0x560 [ 142.213632] ? __next_timer_interrupt+0x140/0x140 [ 142.214455] rcu_gp_kthread+0xbe6/0x2a60 [ 142.215127] ? rwlock_bug.part.2+0x90/0x90 [ 142.215837] ? call_rcu+0x10/0x10 [ 142.216407] ? __sched_text_start+0x8/0x8 [ 142.217099] ? _raw_spin_unlock_irqrestore+0x2d/0x50 [ 142.217948] ? __kthread_parkme+0x4e/0x1a0 [ 142.218661] ? lockdep_hardirqs_on+0x37f/0x560 [ 142.219428] ? __kthread_parkme+0xf5/0x1a0 [ 142.220133] ? call_rcu+0x10/0x10 [ 142.220716] kthread+0x34e/0x410 [ 142.221231] ? kthread_create_on_node+0x100/0x100 [ 142.221935] ret_from_fork+0x27/0x50 [ 142.222502] NMI backtrace for cpu 0 [ 142.223024] CPU: 0 PID: 266 Comm: a.out Not tainted 5.3.7 #2 [ 142.223883] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu 1 04/01/2014 [ 142.225060] Call Trace: [ 142.225395] <IRQ> [ 142.225683] dump_stack+0xa9/0x10e [ 142.226158] ? lapic_can_unplug_cpu+0x21/0x90 [ 142.226741] nmi_cpu_backtrace+0x123/0x140 [ 142.227290] ? lapic_can_unplug_cpu+0x90/0x90 [ 142.227872] nmi_trigger_cpumask_backtrace+0x1aa/0x200 [ 142.228556] rcu_dump_cpu_stacks+0x178/0x1d1 [ 142.229129] rcu_sched_clock_irq+0x10e4/0x1470 [ 142.229729] ? rcu_read_lock_sched_held+0x10f/0x130 [ 142.230443] ? trace_hardirqs_off+0x3b/0x1a0 [ 142.231017] update_process_times+0x28/0x60 [ 142.231581] tick_sched_handle+0x79/0x150 [ 142.232120] tick_sched_timer+0x40/0x110 [ 142.232649] __hrtimer_run_queues+0x308/0xb50 [ 142.233231] ? tick_sched_do_timer+0x150/0x150 [ 142.233820] ? enqueue_hrtimer+0x320/0x320 [ 142.234376] ? ktime_get_update_offsets_now+0x1eb/0x2e0 [ 142.235121] hrtimer_interrupt+0x2af/0x700 [ 142.235746] smp_apic_timer_interrupt+0x104/0x4c0 [ 142.236444] apic_timer_interrupt+0xf/0x20 [ 142.237007] RIP: 0010:_raw_spin_unlock_irqrestore+0x2f/0x50 [ 142.237748] Code: 48 8b 54 24 10 48 83 c7 18 48 89 f3 be 01 00 00 00 e8 25 28 c5 fd 48 89 ef e8 7d d8 c5 fd f6 c7 02 74 11 e8 53 3c e1 fd 53 9d <65> ff 0d b2 ed a2 7c 5b 5d c3 53 9d e8 50 37 e1 fd eb ed 0f 1f 40 [ 142.240486] RSP: 0018:ffff88806d009c28 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff13 [ 142.241695] RAX: 0000000000000007 RBX: 0000000000000206 RCX: 0000000000000002 [ 142.242887] RDX: 0000000000000000 RSI: 0000000000000008 RDI: ffff88806a7f4f04 [ 142.244053] RBP: ffff88806d0239c0 R08: fffffbfff0afdba1 R09: fffffbfff0afdba1 [ 142.245160] R10: 0000000000000001 R11: fffffbfff0afdba0 R12: 1ffff1100da01389 [ 142.246282] R13: ffffffff85b5d8c0 R14: 0000000000000000 R15: ffff88806d0239c0 [ 142.247289] ? apic_timer_interrupt+0xa/0x20 [ 142.247915] add_timer_on+0x243/0x3f0 [ 142.248447] ? __internal_add_timer+0x80/0x80 [ 142.249078] ? mark_held_locks+0x9e/0xe0 [ 142.249646] ? find_next_bit+0xc9/0xf0 [ 142.250198] clocksource_watchdog+0x56a/0x830 [ 142.250839] call_timer_fn+0x17f/0x5d0 [ 142.251379] ? __clocksource_unstable+0x160/0x160 [ 142.252147] ? msleep_interruptible+0x110/0x110 [ 142.252845] ? do_raw_spin_lock+0x11b/0x280 [ 142.253451] ? _raw_spin_unlock_irq+0x24/0x30 [ 142.254083] ? __clocksource_unstable+0x160/0x160 [ 142.254762] ? __clocksource_unstable+0x160/0x160 [ 142.255439] run_timer_softirq+0xbd9/0x10b0 [ 142.256120] ? call_timer_fn+0x5d0/0x5d0 [ 142.256685] ? retint_kernel+0x10/0x10 [ 142.257257] __do_softirq+0x20e/0x93b [ 142.257793] irq_exit+0x175/0x1a0 [ 142.258277] smp_apic_timer_interrupt+0x13e/0x4c0 [ 142.258952] apic_timer_interrupt+0xf/0x20 [ 142.259544] </IRQ> [ 142.259855] RIP: 0010:_raw_spin_unlock_irq+0x2c/0x30 [ 142.260566] Code: 8b 54 24 08 48 89 fb 48 8d 7f 18 be 01 00 00 00 e8 59 28 c5 fd 48 89 df e8 b1 d8 c5 fd e8 8c 3c e1 fd fb 65 ff 0d ec ed a2 7c <5b> c3 66 90 55 53 48 89 fd 48 8b 54 24 10 48 83 c7 18 48 89 f3 be [ 142.263191] RSP: 0018:ffff88805ea77db0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13 [ 142.264253] RAX: 0000000000000007 RBX: ffff88806d032180 RCX: 0000000000000000 [ 142.265253] RDX: 0000000000000000 RSI: 0000000000000006 RDI: ffff88806a7f4f04 [ 142.266393] RBP: ffff88805ea77e08 R08: ffffed100da06431 R09: 0000000000000000 [ 142.267405] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88806ca02f40 [ 142.268516] R13: ffff88806191cf40 R14: ffff88806a7f46c0 R15: 0000000000000402 [ 142.269726] finish_task_switch+0x11d/0x5e0 [ 142.270466] ? finish_task_switch+0xef/0x5e0 [ 142.271161] ? __switch_to+0x5d5/0xeb0 [ 142.271800] ? __switch_to_asm+0x34/0x70 [ 142.272491] __schedule+0x747/0x1440 [ 142.273088] ? __sched_text_start+0x8/0x8 [ 142.273695] schedule+0xb7/0x240 [ 142.274202] exit_to_usermode_loop+0x90/0x180 [ 142.274938] do_syscall_64+0x3bf/0x4c0 [ 142.275621] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 142.276460] RIP: 0033:0x7f41a033f469 [ 142.277082] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ff 49 2b 00 f7 d8 64 89 01 48 [ 142.280244] RSP: 002b:00007ffd745b43e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 142.281443] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f41a033f469 [ 142.282527] RDX: 0000000020000080 RSI: 0000000000005452 RDI: 0000000000000003 [ 142.283679] RBP: 00007ffd745b4400 R08: 00007ffd745b44e0 R09: 00007ffd745b44e0 [ 142.284866] R10: 0000000000000000 R11: 0000000000000246 R12: 00005624bad9a800 [ 142.285969] R13: 00007ffd745b44e0 R14: 0000000000000000 R15: 0000000000000000 [ 298.230662] watchdog: BUG: soft lockup - CPU#0 stuck for 134s! [a.out:266] [ 298.234068] Modules linked in: [ 298.234571] irq event stamp: 10307865 [ 298.235146] hardirqs last enabled at (10307864): [<ffffffff81003c9a>] trace_hardirqs_ on_thunk+0x1a/0x20 [ 298.236589] hardirqs last disabled at (10307865): [<ffffffff81003cba>] trace_hardirqs_ off_thunk+0x1a/0x20 [ 298.238061] softirqs last enabled at (2526): [<ffffffff8380064e>] __do_softirq+0x64e/ 0x93b [ 298.239362] softirqs last disabled at (5969): [<ffffffff811412f5>] irq_exit+0x175/0x1a 0 [ 298.240596] CPU: 0 PID: 266 Comm: a.out Not tainted 5.3.7 #2 [ 298.241461] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu 1 04/01/2014 [ 298.242780] RIP: 0010:_raw_spin_unlock_irq+0x2c/0x30 [ 298.243637] Code: 8b 54 24 08 48 89 fb 48 8d 7f 18 be 01 00 00 00 e8 59 28 c5 fd 48 89 df e8 b1 d8 c5 fd e8 8c 3c e1 fd fb 65 ff 0d ec ed a2 7c <5b> c3 66 90 55 53 48 89 fd 48 8b 54 24 10 48 83 c7 18 48 89 f3 be [ 298.246748] RSP: 0018:ffff88806d009e20 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff13 [ 298.248012] RAX: 0000000000000007 RBX: ffff88806d0239c0 RCX: 0000000000000000 [ 298.249201] RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffff88806a7f4f04 [ 298.250410] RBP: ffff88806d009e98 R08: ffffed100da04739 R09: 0000000000000000 [ 298.251607] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff812e45f0 [ 298.252800] R13: ffff88806d009e98 R14: dffffc0000000000 R15: ffff88806d0239c0 [ 298.254018] FS: 00007f41a0818540(0000) GS:ffff88806d000000(0000) knlGS:00000000000000 00 [ 298.255363] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 298.256352] CR2: 0000000020000080 CR3: 000000006184c000 CR4: 00000000000006f0 [ 298.257564] Call Trace: [ 298.258004] <IRQ> [ 298.258369] run_timer_softirq+0xbc9/0x10b0 [ 298.259093] ? call_timer_fn+0x5d0/0x5d0 [ 298.259766] ? retint_kernel+0x10/0x10 [ 298.260441] __do_softirq+0x20e/0x93b [ 298.261078] irq_exit+0x175/0x1a0 [ 298.261650] smp_apic_timer_interrupt+0x13e/0x4c0 [ 298.262468] apic_timer_interrupt+0xf/0x20 [ 298.263168] </IRQ> [ 298.263539] RIP: 0010:_raw_spin_unlock_irq+0x2c/0x30 [ 298.264388] Code: 8b 54 24 08 48 89 fb 48 8d 7f 18 be 01 00 00 00 e8 59 28 c5 fd 48 89 df e8 b1 d8 c5 fd e8 8c 3c e1 fd fb 65 ff 0d ec ed a2 7c <5b> c3 66 90 55 53 48 89 fd 48 8b 54 24 10 48 83 c7 18 48 89 f3 be [ 298.267510] RSP: 0018:ffff88805ea77db0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13 [ 298.268796] RAX: 0000000000000007 RBX: ffff88806d032180 RCX: 0000000000000000 [ 298.270009] RDX: 0000000000000000 RSI: 0000000000000006 RDI: ffff88806a7f4f04 [ 298.271245] RBP: ffff88805ea77e08 R08: ffffed100da06431 R09: 0000000000000000 [ 298.272489] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88806ca02f40 [ 298.273740] R13: ffff88806191cf40 R14: ffff88806a7f46c0 R15: 0000000000000402 [ 298.275014] finish_task_switch+0x11d/0x5e0 [ 298.275770] ? finish_task_switch+0xef/0x5e0 [ 298.276514] ? __switch_to+0x5d5/0xeb0 [ 298.277150] ? __switch_to_asm+0x34/0x70 [ 298.277839] __schedule+0x747/0x1440 [ 298.278501] ? __sched_text_start+0x8/0x8 [ 298.279223] schedule+0xb7/0x240 [ 298.279813] exit_to_usermode_loop+0x90/0x180 [ 298.280588] do_syscall_64+0x3bf/0x4c0 [ 298.281266] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 298.282168] RIP: 0033:0x7f41a033f469 [ 298.282801] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ff 49 2b 00 f7 d8 64 89 01 48 [ 298.285938] RSP: 002b:00007ffd745b43e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 298.287286] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f41a033f469 [ 298.288529] RDX: 0000000020000080 RSI: 0000000000005452 RDI: 0000000000000003 [ 298.289769] RBP: 00007ffd745b4400 R08: 00007ffd745b44e0 R09: 00007ffd745b44e0 [ 298.291087] R10: 0000000000000000 R11: 0000000000000246 R12: 00005624bad9a800 [ 298.292322] R13: 00007ffd745b44e0 R14: 0000000000000000 R15: 0000000000000000 [ 457.202042] rcu: INFO: rcu_sched self-detected stall on CPU [ 457.203006] rcu: 0-...!: (419854 ticks this GP) idle=e4e/1/0x4000000000000004 soft irq=21700/21700 fqs=0 [ 457.204444] (t=420003 jiffies g=79405 q=2) [ 457.205080] rcu: rcu_sched kthread starved for 420003 jiffies! g79405 f0x0 RCU_GP_WAIT _FQS(5) ->state=0x0 ->cpu=0 [ 457.206616] rcu: RCU grace-period kthread stack dump: [ 457.207388] rcu_sched R running task 30120 10 2 0x80004000 [ 457.208471] Call Trace: [ 457.208867] ? __schedule+0x73f/0x1440 [ 457.209440] ? __sched_text_start+0x8/0x8 [ 457.210060] schedule+0xb7/0x240 [ 457.210563] schedule_timeout+0x3a9/0x9e0 [ 457.211183] ? usleep_range+0x130/0x130 [ 457.211781] ? lockdep_hardirqs_on+0x37f/0x560 [ 457.212472] ? __next_timer_interrupt+0x140/0x140 [ 457.213196] rcu_gp_kthread+0xbe6/0x2a60 [ 457.213807] ? rwlock_bug.part.2+0x90/0x90 [ 457.214455] ? call_rcu+0x10/0x10 [ 457.214978] ? __sched_text_start+0x8/0x8 [ 457.215606] ? _raw_spin_unlock_irqrestore+0x2d/0x50 [ 457.216375] ? __kthread_parkme+0x4e/0x1a0 [ 457.217004] ? lockdep_hardirqs_on+0x37f/0x560 [ 457.217682] ? __kthread_parkme+0xf5/0x1a0 [ 457.218330] ? call_rcu+0x10/0x10 [ 457.218839] kthread+0x34e/0x410 [ 457.219347] ? kthread_create_on_node+0x100/0x100 [ 457.220062] ret_from_fork+0x27/0x50 [ 457.220633] NMI backtrace for cpu 0 [ 457.221186] CPU: 0 PID: 266 Comm: a.out Tainted: G L 5.3.7 #2 [ 457.222256] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu 1 04/01/2014 [ 457.223580] Call Trace: [ 457.223970] <IRQ> [ 457.224293] dump_stack+0xa9/0x10e [ 457.224822] ? lapic_can_unplug_cpu+0x21/0x90 [ 457.225483] nmi_cpu_backtrace+0x123/0x140 [ 457.226123] ? lapic_can_unplug_cpu+0x90/0x90 [ 457.226795] nmi_trigger_cpumask_backtrace+0x1aa/0x200 [ 457.227580] rcu_dump_cpu_stacks+0x178/0x1d1 [ 457.228240] rcu_sched_clock_irq+0x10e4/0x1470 [ 457.228934] ? rcu_read_lock_sched_held+0x10f/0x130 [ 457.229682] ? trace_hardirqs_off+0x3b/0x1a0 [ 457.230333] update_process_times+0x28/0x60 [ 457.230974] tick_sched_handle+0x79/0x150 [ 457.231586] tick_sched_timer+0x40/0x110 [ 457.232192] __hrtimer_run_queues+0x308/0xb50 [ 457.232863] ? tick_sched_do_timer+0x150/0x150 [ 457.233546] ? enqueue_hrtimer+0x320/0x320 [ 457.234188] ? ktime_get_update_offsets_now+0x1eb/0x2e0 [ 457.234989] hrtimer_interrupt+0x2af/0x700 [ 457.235625] smp_apic_timer_interrupt+0x104/0x4c0 [ 457.236344] apic_timer_interrupt+0xf/0x20 [ 457.236978] RIP: 0010:add_timer_on+0x2/0x3f0 [ 457.237640] Code: 48 89 ee 48 89 df 5b 5d 89 c2 e9 29 fc ff ff e8 d4 56 32 00 eb be 48 89 34 24 e8 c9 56 32 00 48 8b 34 24 eb ce 0f 1f 00 41 57 <41> 56 41 89 f6 41 55 41 54 55 53 48 bd 00 00 00 00 00 fc ff df 48 [ 457.240415] RSP: 0018:ffff88806d009cd0 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff13 [ 457.241546] RAX: ffff88806a7f46c0 RBX: 0000000000000000 RCX: ffffffff812e4b41 [ 457.242630] RDX: 0000000000000100 RSI: 0000000000000000 RDI: ffffffff85b5d8a0 [ 457.243702] RBP: 0000000000000033 R08: 0000000000000004 R09: fffffbfff0b6bb04 [ 457.244769] R10: 0000000000000001 R11: fffffbfff0b6bb04 R12: 000000d415081dc8 [ 457.245829] R13: dffffc0000000000 R14: ffffffff84312d38 R15: 0000006a3bc95bd1 [ 457.246921] ? apic_timer_interrupt+0xa/0x20 [ 457.247576] ? clocksource_watchdog+0x551/0x830 [ 457.248271] clocksource_watchdog+0x56a/0x830 [ 457.248940] call_timer_fn+0x17f/0x5d0 [ 457.249511] ? __clocksource_unstable+0x160/0x160 [ 457.250239] ? msleep_interruptible+0x110/0x110 [ 457.250929] ? do_raw_spin_lock+0x11b/0x280 [ 457.251577] ? _raw_spin_unlock_irq+0x24/0x30 [ 457.252238] ? __clocksource_unstable+0x160/0x160 [ 457.252965] ? __clocksource_unstable+0x160/0x160 [ 457.253688] run_timer_softirq+0xbd9/0x10b0 [ 457.254340] ? call_timer_fn+0x5d0/0x5d0 [ 457.254949] ? retint_kernel+0x10/0x10 [ 457.255532] __do_softirq+0x20e/0x93b [ 457.256109] irq_exit+0x175/0x1a0 [ 457.256626] smp_apic_timer_interrupt+0x13e/0x4c0 [ 457.257351] apic_timer_interrupt+0xf/0x20 [ 457.257967] </IRQ> [ 457.258307] RIP: 0010:_raw_spin_unlock_irq+0x2c/0x30 [ 457.259065] Code: 8b 54 24 08 48 89 fb 48 8d 7f 18 be 01 00 00 00 e8 59 28 c5 fd 48 89 df e8 b1 d8 c5 fd e8 8c 3c e1 fd fb 65 ff 0d ec ed a2 7c <5b> c3 66 90 55 53 48 89 fd 48 8b 54 24 10 48 83 c7 18 48 89 f3 be [ 457.261835] RSP: 0018:ffff88805ea77db0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13 [ 457.262985] RAX: 0000000000000007 RBX: ffff88806d032180 RCX: 0000000000000000 [ 457.264055] RDX: 0000000000000000 RSI: 0000000000000006 RDI: ffff88806a7f4f04 [ 457.265142] RBP: ffff88805ea77e08 R08: ffffed100da06431 R09: 0000000000000000 [ 457.266226] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88806ca02f40 [ 457.267303] R13: ffff88806191cf40 R14: ffff88806a7f46c0 R15: 0000000000000402 [ 457.268386] finish_task_switch+0x11d/0x5e0 [ 457.269026] ? finish_task_switch+0xef/0x5e0 [ 457.269688] ? __switch_to+0x5d5/0xeb0 [ 457.270267] ? __switch_to_asm+0x34/0x70 [ 457.270869] __schedule+0x747/0x1440 [ 457.271419] ? __sched_text_start+0x8/0x8 [ 457.272034] schedule+0xb7/0x240 [ 457.272534] exit_to_usermode_loop+0x90/0x180 [ 457.273195] do_syscall_64+0x3bf/0x4c0 [ 457.273773] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 457.274543] RIP: 0033:0x7f41a033f469 [ 457.275097] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ff 49 2b 00 f7 d8 64 89 01 48 [ 457.277868] RSP: 002b:00007ffd745b43e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 457.279005] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f41a033f469 [ 457.280074] RDX: 0000000020000080 RSI: 0000000000005452 RDI: 0000000000000003 [ 457.281141] RBP: 00007ffd745b4400 R08: 00007ffd745b44e0 R09: 00007ffd745b44e0 [ 457.282224] R10: 0000000000000000 R11: 0000000000000246 R12: 00005624bad9a800 [ 457.283301] R13: 00007ffd745b44e0 R14: 0000000000000000 R15: 0000000000000000 [ 457.286158] BUG: workqueue lockup - pool cpus=0 flags=0x4 nice=0 stuck for 392s! [ 457.287398] Showing busy workqueues and worker pools: [ 457.288158] workqueue events: flags=0x0 [ 457.288815] pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=3/256 [ 457.289828] pending: e1000_watchdog, check_corruption, vmstat_shepherd [ 457.290953] workqueue events_power_efficient: flags=0x80 [ 457.291755] pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=6/256 [ 457.292663] pending: crda_timeout_work, reg_check_chans_work, check_lifetime, gc_w orker, neigh_periodic_work, neigh_periodic_work [ 457.294489] workqueue events_freezable_power_: flags=0x84 [ 457.295299] pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 [ 457.296207] pending: disk_events_workfn [ 457.296854] workqueue writeback: flags=0x4e [ 457.297525] pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 [ 457.298877] pending: wb_workfn [ 457.299410] [ 457.299412] ====================================================== [ 457.299414] WARNING: possible circular locking dependency detected [ 457.299416] 5.3.7 #2 Tainted: G L [ 457.299417] ------------------------------------------------------ [ 457.299419] a.out/266 is trying to acquire lock: [ 457.299420] 0000000091dad783 (console_owner){-.-.}, at: console_unlock+0x387/0xaf0 [ 457.299425] [ 457.299426] but task is already holding lock: [ 457.299427] 000000000e0f7f1e (&pool->lock/1){-.-.}, at: show_workqueue_state+0x53c/0x1 3a0 [ 457.299433] [ 457.299434] which lock already depends on the new lock. [ 457.299435] [ 457.299436] [ 457.299438] the existing dependency chain (in reverse order) is: [ 457.299439] [ 457.299439] -> #2 (&pool->lock/1){-.-.}: [ 457.299454] _raw_spin_lock+0x27/0x40 [ 457.299456] __queue_work+0x25b/0x1030 [ 457.299457] queue_work_on+0x81/0x90 [ 457.299459] serial8250_rx_chars+0xac/0xd0 [ 457.299460] serial8250_handle_irq.part.25+0x25a/0x2b0 [ 457.299462] serial8250_default_handle_irq+0xf3/0x120 [ 457.299463] serial8250_interrupt+0xe8/0x180 [ 457.299465] __handle_irq_event_percpu+0xfa/0x700 [ 457.299466] handle_irq_event_percpu+0x76/0x140 [ 457.299468] handle_irq_event+0xa1/0x130 [ 457.299469] handle_edge_irq+0x207/0x7f0 [ 457.299470] handle_irq+0x39/0x50 [ 457.299471] do_IRQ+0x73/0x190 [ 457.299473] ret_from_intr+0x0/0x1d [ 457.299474] delay_tsc+0x42/0x80 [ 457.299475] handle_mm_fault+0x107/0x840 [ 457.299477] __do_page_fault+0x4eb/0xab0 [ 457.299478] async_page_fault+0x34/0x40 [ 457.299479] [ 457.299480] -> #1 (&port_lock_key){-.-.}: [ 457.299484] _raw_spin_lock_irqsave+0x30/0x40 [ 457.299486] serial8250_console_write+0x155/0x7b0 [ 457.299487] console_unlock+0x794/0xaf0 [ 457.299488] vprintk_emit+0x108/0x320 [ 457.299490] vprintk_func+0x52/0xe0 [ 457.299491] printk+0xb2/0xdd [ 457.299492] register_console+0x6ba/0xb40 [ 457.299494] univ8250_console_init+0x2c/0x35 [ 457.299495] console_init+0x35c/0x4f0 [ 457.299496] start_kernel+0x546/0x7dd [ 457.299498] secondary_startup_64+0xa4/0xb0 [ 457.299498] [ 457.299499] -> #0 (console_owner){-.-.}: [ 457.299504] __lock_acquire+0x254f/0x3420 [ 457.299505] lock_acquire+0x11c/0x350 [ 457.299506] console_unlock+0x3f3/0xaf0 [ 457.299508] vprintk_emit+0x108/0x320 [ 457.299509] vprintk_func+0x52/0xe0 [ 457.299510] printk+0xb2/0xdd [ 457.299512] show_workqueue_state+0x685/0x13a0 [ 457.299513] wq_watchdog_timer_fn+0x408/0x540 [ 457.299514] call_timer_fn+0x17f/0x5d0 [ 457.299516] run_timer_softirq+0x577/0x10b0 [ 457.299517] __do_softirq+0x20e/0x93b [ 457.299518] irq_exit+0x175/0x1a0 [ 457.299520] smp_apic_timer_interrupt+0x13e/0x4c0 [ 457.299521] apic_timer_interrupt+0xf/0x20 [ 457.299523] _raw_spin_unlock_irq+0x2c/0x30 [ 457.299524] finish_task_switch+0x11d/0x5e0 [ 457.299525] __schedule+0x747/0x1440 [ 457.299527] schedule+0xb7/0x240 [ 457.299528] exit_to_usermode_loop+0x90/0x180 [ 457.299529] do_syscall_64+0x3bf/0x4c0 [ 457.299531] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 457.299532] [ 457.299533] other info that might help us debug this: [ 457.299534] [ 457.299535] Chain exists of: [ 457.299536] console_owner --> &port_lock_key --> &pool->lock/1 [ 457.299542] [ 457.299543] Possible unsafe locking scenario: [ 457.299544] [ 457.299546] CPU0 CPU1 [ 457.299547] ---- ---- [ 457.299548] lock(&pool->lock/1); [ 457.299552] lock(&port_lock_key); [ 457.299555] lock(&pool->lock/1); [ 457.299558] lock(console_owner); [ 457.299561] [ 457.299562] *** DEADLOCK *** [ 457.299562] [ 457.299564] 4 locks held by a.out/266: [ 457.299564] #0: 00000000d69171a5 ((&wq_watchdog_timer)){+.-.}, at: call_timer_fn+0xdc /0x5d0 [ 457.299570] #1: 0000000035eeb611 (rcu_read_lock){....}, at: show_workqueue_state+0x0/ 0x13a0 [ 457.299576] #2: 000000000e0f7f1e (&pool->lock/1){-.-.}, at: show_workqueue_state+0x53 c/0x13a0 [ 457.299582] #3: 0000000098fc1a1b (console_lock){+.+.}, at: vprintk_emit+0xfa/0x320 [ 457.299587] [ 457.299588] stack backtrace: [ 457.299590] CPU: 0 PID: 266 Comm: a.out Tainted: G L 5.3.7 #2 [ 457.299592] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu 1 04/01/2014 [ 457.299593] Call Trace: [ 457.299594] <IRQ> [ 457.299600] dump_stack+0xa9/0x10e [ 457.299602] check_noncircular+0x385/0x410 [ 457.299603] ? print_circular_bug+0x2d0/0x2d0 [ 457.299605] ? stack_trace_save+0x98/0xd0 [ 457.299606] ? hlock_class+0x120/0x120 [ 457.299607] ? __lock_acquire+0x254f/0x3420 [ 457.299608] __lock_acquire+0x254f/0x3420 [ 457.299610] ? console_unlock+0x3ce/0xaf0 [ 457.299611] ? lockdep_hardirqs_on+0x560/0x560 [ 457.299612] ? lock_downgrade+0x6d0/0x6d0 [ 457.299613] lock_acquire+0x11c/0x350 [ 457.299615] ? console_unlock+0x387/0xaf0 [ 457.299616] console_unlock+0x3f3/0xaf0 [ 457.299617] ? console_unlock+0x387/0xaf0 [ 457.299618] vprintk_emit+0x108/0x320 [ 457.299620] vprintk_func+0x52/0xe0 [ 457.299621] printk+0xb2/0xdd [ 457.299622] ? kmsg_dump_rewind_nolock+0xd9/0xd9 [ 457.299623] ? pr_cont_pool_info+0x17/0x170 [ 457.299625] show_workqueue_state+0x685/0x13a0 [ 457.299626] ? print_worker_info+0x2d0/0x2d0 [ 457.299627] wq_watchdog_timer_fn+0x408/0x540 [ 457.299629] ? show_workqueue_state+0x13a0/0x13a0 [ 457.299630] ? run_timer_softirq+0x567/0x10b0 [ 457.299631] call_timer_fn+0x17f/0x5d0 [ 457.299633] ? show_workqueue_state+0x13a0/0x13a0 [ 457.299634] ? msleep_interruptible+0x110/0x110 [ 457.299635] ? do_raw_spin_lock+0x11b/0x280 [ 457.299637] ? _raw_spin_unlock_irq+0x24/0x30 [ 457.299638] ? show_workqueue_state+0x13a0/0x13a0 [ 457.299640] ? show_workqueue_state+0x13a0/0x13a0 [ 457.299641] run_timer_softirq+0x577/0x10b0 [ 457.299642] ? call_timer_fn+0x5d0/0x5d0 [ 457.299643] ? retint_kernel+0x10/0x10 [ 457.299645] __do_softirq+0x20e/0x93b [ 457.299646] irq_exit+0x175/0x1a0 [ 457.299647] smp_apic_timer_interrupt+0x13e/0x4c0 [ 457.299648] apic_timer_interrupt+0xf/0x20 [ 457.299649] </IRQ> [ 457.299651] RIP: 0010:_raw_spin_unlock_irq+0x2c/0x30 [ 457.299655] Code: 8b 54 24 08 48 89 fb 48 8d 7f 18 be 01 00 00 00 e8 59 28 c5 fd 48 89 df e8 b1 d8 c5 fd e8 8c 3c e1 fd fb 65 ff 0d ec ed a2 7c <5b> c3 66 90 55 53 48 89 fd 48 8b 54 24 10 48 83 c7 18 48 89 f3 be [ 457.299657] RSP: 0018:ffff88805ea77db0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13 [ 457.299660] RAX: 0000000000000007 RBX: ffff88806d032180 RCX: 0000000000000000 [ 457.299662] RDX: 0000000000000000 RSI: 0000000000000006 RDI: ffff88806a7f4f04 [ 457.299664] RBP: ffff88805ea77e08 R08: ffffed100da06431 R09: 0000000000000000 [ 457.299666] R10: 0000000000000000 R11: 0000000000000000 R12: ffff88806ca02f40 [ 457.299667] R13: ffff88806191cf40 R14: ffff88806a7f46c0 R15: 0000000000000402 [ 457.299669] finish_task_switch+0x11d/0x5e0 [ 457.299670] ? finish_task_switch+0xef/0x5e0 [ 457.299671] ? __switch_to+0x5d5/0xeb0 [ 457.299673] ? __switch_to_asm+0x34/0x70 [ 457.299674] __schedule+0x747/0x1440 [ 457.299675] ? __sched_text_start+0x8/0x8 [ 457.299676] schedule+0xb7/0x240 [ 457.299678] exit_to_usermode_loop+0x90/0x180 [ 457.299679] do_syscall_64+0x3bf/0x4c0 [ 457.299680] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 457.299682] RIP: 0033:0x7f41a033f469 [ 457.299686] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ff 49 2b 00 f7 d8 64 89 01 48 [ 457.299687] RSP: 002b:00007ffd745b43e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 457.299690] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f41a033f469 [ 457.299692] RDX: 0000000020000080 RSI: 0000000000005452 RDI: 0000000000000003 [ 457.299694] RBP: 00007ffd745b4400 R08: 00007ffd745b44e0 R09: 00007ffd745b44e0 [ 457.299696] R10: 0000000000000000 R11: 0000000000000246 R12: 00005624bad9a800 [ 457.299698] R13: 00007ffd745b44e0 R14: 0000000000000000 R15: 0000000000000000 [ 584.836419] workqueue kblockd: flags=0x18 [ 671.030109] pwq 1: cpus=0 node=0 flags=0x0 nice=-20 active=2/256 [ 671.034279] pending: blk_mq_timeout_work, blk_mq_timeout_work qemu-system-x86_64: terminating on signal 15 from pid 41739 ()