syzbot


INFO: rcu detected stall in queue_delayed_work_on

Status: auto-closed as invalid on 2021/12/14 09:42
Reported-by: syzbot+@syzkaller.appspotmail.com
First crash: 443d, last: 443d

Sample crash report:
rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
rcu: 	0-...!: (0 ticks this GP) idle=d65/1/0x4000000000000000 softirq=41315/41315 fqs=0 
	(detected by 1, t=10502 jiffies, g=63941, q=112)
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 5 Comm: kworker/0:0 Not tainted 5.15.0-rc1-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: rcu_gp process_srcu
RIP: 0010:native_save_fl arch/x86/include/asm/irqflags.h:29 [inline]
RIP: 0010:arch_local_save_flags arch/x86/include/asm/irqflags.h:70 [inline]
RIP: 0010:arch_local_irq_save arch/x86/include/asm/irqflags.h:106 [inline]
RIP: 0010:lock_is_held_type+0x63/0x190 kernel/locking/lockdep.c:5664
Code: fb 00 00 00 65 4c 8b 2c 25 c0 ef 01 00 41 83 bd f4 09 00 00 00 0f 85 e4 00 00 00 41 89 f6 49 89 ff 48 c7 04 24 00 00 00 00 9c <8f> 04 24 4c 8b 24 24 fa 48 c7 c7 a0 f9 4e 8a e8 69 11 00 00 65 ff
RSP: 0018:ffffc90000007a10 EFLAGS: 00000046
RAX: 0000000000000000 RBX: 00000000ffffffff RCX: 0000000080010002
RDX: 0000000000000000 RSI: 00000000ffffffff RDI: ffffffff8c91c0e0
RBP: ffffc90000007af0 R08: dffffc0000000000 R09: ffffed10173864a2
R10: ffffed10173864a2 R11: 0000000000000000 R12: dffffc0000000000
R13: ffff888012370000 R14: 00000000ffffffff R15: ffffffff8c91c0e0
FS:  0000000000000000(0000) GS:ffff8880b9c00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000014a53ad CR3: 000000008287c000 CR4: 00000000001506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 lock_is_held include/linux/lockdep.h:283 [inline]
 rcu_read_lock_sched_held+0x89/0x130 kernel/rcu/update.c:125
 trace_lock_release+0x4f/0x150 include/trace/events/lock.h:58
 lock_release+0x82/0x810 kernel/locking/lockdep.c:5636
 __raw_spin_unlock include/linux/spinlock_api_smp.h:150 [inline]
 _raw_spin_unlock+0x12/0x40 kernel/locking/spinlock.c:186
 spin_unlock include/linux/spinlock.h:403 [inline]
 advance_sched+0x68b/0x930 net/sched/sch_taprio.c:759
 __run_hrtimer kernel/time/hrtimer.c:1685 [inline]
 __hrtimer_run_queues+0x50b/0xa60 kernel/time/hrtimer.c:1749
 hrtimer_interrupt+0x3b3/0x1040 kernel/time/hrtimer.c:1811
 local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1086 [inline]
 __sysvec_apic_timer_interrupt+0xf9/0x270 arch/x86/kernel/apic/apic.c:1103
 sysvec_apic_timer_interrupt+0x8c/0xb0 arch/x86/kernel/apic/apic.c:1097
 </IRQ>
 asm_sysvec_apic_timer_interrupt+0x12/0x20
RIP: 0010:queue_delayed_work_on+0x1e5/0x230 kernel/workqueue.c:1707
Code: 4d 85 f6 75 16 e8 5b ed 2d 00 eb 15 e8 54 ed 2d 00 e8 9f cc a3 08 4d 85 f6 74 ea e8 45 ed 2d 00 fb 48 c7 44 24 20 0e 36 e0 45 <4b> c7 04 27 00 00 00 00 66 43 c7 44 27 09 00 00 43 c6 44 27 0b 00
RSP: 0018:ffffc90000ca7b80 EFLAGS: 00000293
RAX: ffffffff815489eb RBX: 0000000000000000 RCX: ffff888012370000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
RBP: ffffc90000ca7c50 R08: ffffffff815489c1 R09: fffffbfff1fa2fc3
R10: fffffbfff1fa2fc3 R11: 0000000000000000 R12: 1ffff92000194f74
R13: 0000000000000046 R14: 0000000000000200 R15: dffffc0000000000
 process_one_work+0x853/0x1140 kernel/workqueue.c:2297
 worker_thread+0xac1/0x1320 kernel/workqueue.c:2444
 kthread+0x453/0x480 kernel/kthread.c:319
 ret_from_fork+0x1f/0x30
rcu: rcu_preempt kthread timer wakeup didn't happen for 10501 jiffies! g63941 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
rcu: 	Possible timer handling issue on cpu=0 timer-softirq=20803
rcu: rcu_preempt kthread starved for 10502 jiffies! g63941 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=0
rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
rcu: RCU grace-period kthread stack dump:
task:rcu_preempt     state:I stack:26768 pid:   14 ppid:     2 flags:0x00004000
Call Trace:
 context_switch kernel/sched/core.c:4940 [inline]
 __schedule+0xc8d/0x1270 kernel/sched/core.c:6287
 schedule+0x14b/0x210 kernel/sched/core.c:6366
 schedule_timeout+0x1b9/0x300 kernel/time/timer.c:1881
 rcu_gp_fqs_loop+0x1fd/0x770 kernel/rcu/tree.c:1957
 rcu_gp_kthread+0xa5/0x350 kernel/rcu/tree.c:2130
 kthread+0x453/0x480 kernel/kthread.c:319
 ret_from_fork+0x1f/0x30
rcu: Stack dump where RCU GP kthread last ran:
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 5 Comm: kworker/0:0 Not tainted 5.15.0-rc1-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: rcu_gp process_srcu
RIP: 0010:preempt_count kernel/rcu/tree.c:1161 [inline]
RIP: 0010:rcu_lockdep_current_cpu_online+0x2/0x130 kernel/rcu/tree.c:1166
Code: 89 df e8 91 dc 60 00 eb d1 44 89 f6 48 c7 c7 80 0b 92 8c e8 d0 2c c7 02 eb 89 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 41 57 <41> 56 41 54 53 65 8b 0d 5a fa 94 7e b0 01 f7 c1 00 00 f0 00 0f 85
RSP: 0018:ffffc90000007c50 EFLAGS: 00000002
RAX: 000000000006ad01 RBX: 1ffff92000000f8c RCX: ffffffff816cf448
RDX: 0000000000000000 RSI: 0000000000000004 RDI: ffff8880b9c32508
RBP: ffffc90000007cf0 R08: dffffc0000000000 R09: ffffed10173864a2
R10: ffffed10173864a2 R11: 0000000000000000 R12: ffff8880b9c22240
R13: dffffc0000000000 R14: dffffc0000000000 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff8880b9c00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000014a53ad CR3: 000000008287c000 CR4: 00000000001506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 rcu_read_lock_held_common kernel/rcu/update.c:112 [inline]
 rcu_read_lock_sched_held+0x74/0x130 kernel/rcu/update.c:123
 trace_hrtimer_cancel+0xab/0x260 include/trace/events/timer.h:290
 debug_deactivate kernel/time/hrtimer.c:482 [inline]
 __run_hrtimer kernel/time/hrtimer.c:1653 [inline]
 __hrtimer_run_queues+0x301/0xa60 kernel/time/hrtimer.c:1749
 hrtimer_interrupt+0x3b3/0x1040 kernel/time/hrtimer.c:1811
 local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1086 [inline]
 __sysvec_apic_timer_interrupt+0xf9/0x270 arch/x86/kernel/apic/apic.c:1103
 sysvec_apic_timer_interrupt+0x8c/0xb0 arch/x86/kernel/apic/apic.c:1097
 </IRQ>
 asm_sysvec_apic_timer_interrupt+0x12/0x20
RIP: 0010:queue_delayed_work_on+0x1e5/0x230 kernel/workqueue.c:1707
Code: 4d 85 f6 75 16 e8 5b ed 2d 00 eb 15 e8 54 ed 2d 00 e8 9f cc a3 08 4d 85 f6 74 ea e8 45 ed 2d 00 fb 48 c7 44 24 20 0e 36 e0 45 <4b> c7 04 27 00 00 00 00 66 43 c7 44 27 09 00 00 43 c6 44 27 0b 00
RSP: 0018:ffffc90000ca7b80 EFLAGS: 00000293
RAX: ffffffff815489eb RBX: 0000000000000000 RCX: ffff888012370000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
RBP: ffffc90000ca7c50 R08: ffffffff815489c1 R09: fffffbfff1fa2fc3
R10: fffffbfff1fa2fc3 R11: 0000000000000000 R12: 1ffff92000194f74
R13: 0000000000000046 R14: 0000000000000200 R15: dffffc0000000000
 process_one_work+0x853/0x1140 kernel/workqueue.c:2297
 worker_thread+0xac1/0x1320 kernel/workqueue.c:2444
 kthread+0x453/0x480 kernel/kthread.c:319
 ret_from_fork+0x1f/0x30
watchdog: BUG: soft lockup - CPU#1 stuck for 225s! [kworker/u4:1:10]
Modules linked in:
irq event stamp: 11578858
hardirqs last  enabled at (11578857): [<ffffffff8a000c02>] asm_sysvec_apic_timer_interrupt+0x12/0x20
hardirqs last disabled at (11578858): [<ffffffff89f84f3a>] sysvec_apic_timer_interrupt+0xa/0xb0 arch/x86/kernel/apic/apic.c:1097
softirqs last  enabled at (11531034): [<ffffffff814f447c>] __irq_exit_rcu+0xec/0x170 kernel/softirq.c:636
softirqs last disabled at (11530997): [<ffffffff814f447c>] __irq_exit_rcu+0xec/0x170 kernel/softirq.c:636
CPU: 1 PID: 10 Comm: kworker/u4:1 Not tainted 5.15.0-rc1-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: events_unbound toggle_allocation_gate
RIP: 0010:csd_lock_wait kernel/smp.c:440 [inline]
RIP: 0010:smp_call_function_many_cond+0xbb2/0xda0 kernel/smp.c:969
Code: 83 e6 01 31 ff e8 5e a1 0b 00 41 83 e7 01 49 bf 00 00 00 00 00 fc ff df 75 0e e8 39 9d 0b 00 eb 4c 0f 1f 80 00 00 00 00 f3 90 <42> 0f b6 04 3b 84 c0 75 11 41 f7 45 00 01 00 00 00 74 2b e8 16 9d
RSP: 0018:ffffc90000cf7820 EFLAGS: 00000293
RAX: ffffffff8176da1a RBX: 1ffff11017387305 RCX: ffff888012379c80
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000000
RBP: ffffc90000cf7960 R08: ffffffff8176d9e2 R09: ffffffff8434e0f0
R10: 0000000000000009 R11: ffff888012379c80 R12: 0000000000000000
R13: ffff8880b9c39828 R14: ffff8880b9d325c0 R15: dffffc0000000000
FS:  0000000000000000(0000) GS:ffff8880b9d00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000555e972228d8 CR3: 000000000c68e000 CR4: 00000000001506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 on_each_cpu_cond_mask+0x3b/0x80 kernel/smp.c:1135
 on_each_cpu include/linux/smp.h:71 [inline]
 text_poke_sync arch/x86/kernel/alternative.c:929 [inline]
 text_poke_bp_batch+0x310/0x940 arch/x86/kernel/alternative.c:1114
 text_poke_flush arch/x86/kernel/alternative.c:1268 [inline]
 text_poke_finish+0x16/0x30 arch/x86/kernel/alternative.c:1275
 arch_jump_label_transform_apply+0x13/0x20 arch/x86/kernel/jump_label.c:146
 static_key_enable_cpuslocked+0x12d/0x250 kernel/jump_label.c:177
 static_key_enable+0x16/0x20 kernel/jump_label.c:190
 toggle_allocation_gate+0xbf/0x460 mm/kfence/core.c:626
 process_one_work+0x853/0x1140 kernel/workqueue.c:2297
 worker_thread+0xac1/0x1320 kernel/workqueue.c:2444
 kthread+0x453/0x480 kernel/kthread.c:319
 ret_from_fork+0x1f/0x30
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 5 Comm: kworker/0:0 Not tainted 5.15.0-rc1-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: rcu_gp process_srcu
RIP: 0010:mark_lock+0x14a/0x1e00
Code: 84 c0 0f 85 41 10 00 00 8a 43 02 24 03 3c 01 ba 09 00 00 00 83 da 00 41 bd 01 00 00 00 48 89 d0 48 89 54 24 10 89 d1 41 d3 e5 <48> 89 74 24 38 48 8d 5e 20 48 89 d8 48 c1 e8 03 48 89 44 24 18 42
RSP: 0018:ffffc90000007780 EFLAGS: 00000006
RAX: 0000000000000008 RBX: ffff888012370a68 RCX: 0000000000000008
RDX: 0000000000000008 RSI: ffff888012370a48 RDI: ffff888012370000
RBP: ffffc90000007970 R08: dffffc0000000000 R09: fffffbfff1fa2fe7
R10: fffffbfff1fa2fe7 R11: 0000000000000000 R12: 1ffff92000000efc
R13: 0000000000000100 R14: ffff888012370000 R15: dffffc0000000000
FS:  0000000000000000(0000) GS:ffff8880b9c00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000014a53ad CR3: 000000008287c000 CR4: 00000000001506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 mark_usage kernel/locking/lockdep.c:4514 [inline]
 __lock_acquire+0xd38/0x2b00 kernel/locking/lockdep.c:4969
 lock_acquire+0x19f/0x4d0 kernel/locking/lockdep.c:5625
 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
 _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:154
 spin_lock include/linux/spinlock.h:363 [inline]
 advance_sched+0x4c/0x930 net/sched/sch_taprio.c:710
 __run_hrtimer kernel/time/hrtimer.c:1685 [inline]
 __hrtimer_run_queues+0x50b/0xa60 kernel/time/hrtimer.c:1749
 hrtimer_interrupt+0x3b3/0x1040 kernel/time/hrtimer.c:1811
 local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1086 [inline]
 __sysvec_apic_timer_interrupt+0xf9/0x270 arch/x86/kernel/apic/apic.c:1103
 sysvec_apic_timer_interrupt+0x8c/0xb0 arch/x86/kernel/apic/apic.c:1097
 </IRQ>
 asm_sysvec_apic_timer_interrupt+0x12/0x20
RIP: 0010:queue_delayed_work_on+0x1e5/0x230 kernel/workqueue.c:1707
Code: 4d 85 f6 75 16 e8 5b ed 2d 00 eb 15 e8 54 ed 2d 00 e8 9f cc a3 08 4d 85 f6 74 ea e8 45 ed 2d 00 fb 48 c7 44 24 20 0e 36 e0 45 <4b> c7 04 27 00 00 00 00 66 43 c7 44 27 09 00 00 43 c6 44 27 0b 00
RSP: 0018:ffffc90000ca7b80 EFLAGS: 00000293
RAX: ffffffff815489eb RBX: 0000000000000000 RCX: ffff888012370000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
RBP: ffffc90000ca7c50 R08: ffffffff815489c1 R09: fffffbfff1fa2fc3
R10: fffffbfff1fa2fc3 R11: 0000000000000000 R12: 1ffff92000194f74
R13: 0000000000000046 R14: 0000000000000200 R15: dffffc0000000000
 process_one_work+0x853/0x1140 kernel/workqueue.c:2297
 worker_thread+0xac1/0x1320 kernel/workqueue.c:2444
 kthread+0x453/0x480 kernel/kthread.c:319
 ret_from_fork+0x1f/0x30
----------------
Code disassembly (best guess):
   0:	fb                   	sti
   1:	00 00                	add    %al,(%rax)
   3:	00 65 4c             	add    %ah,0x4c(%rbp)
   6:	8b 2c 25 c0 ef 01 00 	mov    0x1efc0,%ebp
   d:	41 83 bd f4 09 00 00 	cmpl   $0x0,0x9f4(%r13)
  14:	00
  15:	0f 85 e4 00 00 00    	jne    0xff
  1b:	41 89 f6             	mov    %esi,%r14d
  1e:	49 89 ff             	mov    %rdi,%r15
  21:	48 c7 04 24 00 00 00 	movq   $0x0,(%rsp)
  28:	00
  29:	9c                   	pushfq
* 2a:	8f 04 24             	popq   (%rsp) <-- trapping instruction
  2d:	4c 8b 24 24          	mov    (%rsp),%r12
  31:	fa                   	cli
  32:	48 c7 c7 a0 f9 4e 8a 	mov    $0xffffffff8a4ef9a0,%rdi
  39:	e8 69 11 00 00       	callq  0x11a7
  3e:	65                   	gs
  3f:	ff                   	.byte 0xff

Crashes (1):
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Title
ci-upstream-kasan-gce-smack-root 2021/09/15 09:40 upstream 1619b69edce1 07e953c1 .config log report info INFO: rcu detected stall in queue_delayed_work_on
* Struck through repros no longer work on HEAD.