Bug 205435

Summary: Possible circular locking dependency and a possible rcu stall problem
Product: Timers Reporter: ddoe404
Component: OtherAssignee: other_other
Status: NEW ---    
Severity: normal CC: ddoe404
Priority: P1    
Hardware: Intel   
OS: Linux   
Kernel Version: 5.3.7 Subsystem:
Regression: No Bisected commit-id:
Attachments: The repro.c file

Description ddoe404 2019-11-05 08:53:21 UTC 
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 ()