syzbot


INFO: rcu detected stall in fq_pie_timer (2)

Status: upstream: reported C repro on 2023/12/27 13:54
Subsystems: net
[Documentation on labels]
Reported-by: syzbot+15c3ba3f7ca8ced0914d@syzkaller.appspotmail.com
First crash: 114d, last: 67d
Cause bisection: introduced by (bisect log) :
commit ec97ecf1ebe485a17cd8395a5f35e6b80b57665a
Author: Mohit P. Tahiliani <tahiliani@nitk.edu.in>
Date: Wed Jan 22 18:22:33 2020 +0000

  net: sched: add Flow Queue PIE packet scheduler

Crash: INFO: rcu detected stall in fq_pie_timer (log)
Repro: C syz .config
  
Discussions (1)
Title Replies (including bot) Last reply
[syzbot] [net?] INFO: rcu detected stall in fq_pie_timer (2) 2 (5) 2023/12/29 11:10
Similar bugs (7)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: rcu detected stall in fq_pie_timer net C error 35 809d 1027d 20/26 fixed on 2022/03/08 16:11
linux-5.15 INFO: rcu detected stall in fq_pie_timer origin:lts-only C done 23 238d 328d 0/3 upstream: reported C repro on 2023/05/22 23:26
upstream BUG: soft lockup in fq_pie_timer (2) net C error done 3 355d 422d 0/26 closed as invalid on 2023/05/26 05:46
upstream BUG: soft lockup in fq_pie_timer net C error error 10 551d 588d 0/26 closed as invalid on 2022/11/18 11:06
linux-6.1 BUG: soft lockup in fq_pie_timer (2) origin:upstream C inconclusive 4 114d 230d 0/3 upstream: reported C repro on 2023/08/29 01:49
upstream BUG: soft lockup in fq_pie_timer (4) net syz 5 216d 266d 23/26 fixed on 2023/10/12 12:48
linux-6.1 BUG: soft lockup in fq_pie_timer C done 7 310d 318d 3/3 fixed on 2023/07/22 07:09
Last patch testing requests (3)
Created Duration User Patch Repo Result
2024/01/06 15:32 19m retest repro net report log
2023/12/29 10:46 23m hdanton@sina.com patch https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master report log
2023/12/28 12:07 19m hdanton@sina.com patch https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master report log
Fix bisection attempts (1)
Created Duration User Patch Repo Result
2024/02/07 18:25 4h05m bisect fix net job log (0) log

Sample crash report:
rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
rcu: 	(detected by 1, t=10502 jiffies, g=9389, q=958 ncpus=2)
rcu: All QSes seen, last rcu_preempt kthread activity 10498 (4294962885-4294952387), jiffies_till_next_fqs=1, root ->qsmask 0x0
rcu: rcu_preempt kthread starved for 10499 jiffies! g9389 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=1
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:R  running task     stack:28752 pid:17    tgid:17    ppid:2      flags:0x00004008
Call Trace:
 <IRQ>
 sched_show_task kernel/sched/core.c:9146 [inline]
 sched_show_task+0x42e/0x650 kernel/sched/core.c:9120
 rcu_check_gp_kthread_starvation+0x19f/0x450 kernel/rcu/tree_stall.h:548
 print_other_cpu_stall kernel/rcu/tree_stall.h:656 [inline]
 check_cpu_stall kernel/rcu/tree_stall.h:796 [inline]
 rcu_pending kernel/rcu/tree.c:3891 [inline]
 rcu_sched_clock_irq+0x2269/0x3150 kernel/rcu/tree.c:2259
 update_process_times+0x17b/0x220 kernel/time/timer.c:2071
 tick_sched_handle+0x8e/0x170 kernel/time/tick-sched.c:255
 tick_nohz_highres_handler+0xe9/0x110 kernel/time/tick-sched.c:1516
 __run_hrtimer kernel/time/hrtimer.c:1688 [inline]
 __hrtimer_run_queues+0x647/0xc20 kernel/time/hrtimer.c:1752
 hrtimer_interrupt+0x31b/0x800 kernel/time/hrtimer.c:1814
 local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1065 [inline]
 __sysvec_apic_timer_interrupt+0x105/0x400 arch/x86/kernel/apic/apic.c:1082
 sysvec_apic_timer_interrupt+0x43/0xb0 arch/x86/kernel/apic/apic.c:1076
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:649
RIP: 0010:div_u64_rem include/linux/math64.h:29 [inline]
RIP: 0010:div_u64 include/linux/math64.h:130 [inline]
RIP: 0010:pie_calculate_probability+0x284/0x850 net/sched/sch_pie.c:345
Code: 89 c5 48 89 6c 24 38 e8 fa 47 e6 f8 47 8d 24 a4 31 d2 4c 89 ff 43 8d 0c 24 49 c1 ee 02 48 b8 ff ff ff ff ff ff ff 00 48 f7 f1 <48> 89 c5 48 89 c6 48 c1 eb 02 49 89 cc e8 da 42 e6 f8 49 39 ef 73
RSP: 0018:ffffc900001f0bb8 EFLAGS: 00000207
RAX: 0000068db8bac710 RBX: 000000002af31dc4 RCX: 0000000000002710
RDX: 0000000000001eff RSI: ffffffff88a129d6 RDI: 0000000000000000
RBP: 00004189374bc6a7 R08: 0000000000000005 R09: 00000000000f4240
R10: 00000000000003e8 R11: 0000000000000002 R12: 0000000000001388
R13: 0000000000000004 R14: 000000000112e0be R15: 0000000000000000
 fq_pie_timer+0x215/0x5a0 net/sched/sch_fq_pie.c:391
 call_timer_fn+0x193/0x590 kernel/time/timer.c:1700
 expire_timers kernel/time/timer.c:1751 [inline]
 __run_timers+0x764/0xb20 kernel/time/timer.c:2022
 run_timer_softirq+0x58/0xd0 kernel/time/timer.c:2035
 __do_softirq+0x21a/0x8de kernel/softirq.c:553
 invoke_softirq kernel/softirq.c:427 [inline]
 __irq_exit_rcu kernel/softirq.c:632 [inline]
 irq_exit_rcu+0xb7/0x120 kernel/softirq.c:644
 sysvec_apic_timer_interrupt+0x95/0xb0 arch/x86/kernel/apic/apic.c:1076
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:649
RIP: 0010:finish_task_switch.isra.0+0x223/0xca0 kernel/sched/core.c:5250
Code: 0a 00 00 44 8b 0d 35 8b be 0d 45 85 c9 0f 85 c0 01 00 00 48 89 df e8 cc f8 ff ff e8 57 47 33 00 fb 65 48 8b 1c 25 c0 bc 03 00 <48> 8d bb d8 15 00 00 48 b8 00 00 00 00 00 fc ff df 48 89 fa 48 c1
RSP: 0018:ffffc90000167a08 EFLAGS: 00000206
RAX: 000000000001e735 RBX: ffff888017e48000 RCX: 1ffffffff1e320a9
RDX: 0000000000000000 RSI: ffffffff8accaec0 RDI: ffffffff8b2efba0
RBP: ffffc90000167a50 R08: 0000000000000001 R09: 0000000000000001
R10: ffffffff8f1937d7 R11: 0000000000000000 R12: ffff8880b993d478
R13: ffff888026c53b80 R14: 0000000000000000 R15: ffff8880b993c700
 context_switch kernel/sched/core.c:5379 [inline]
 __schedule+0xee3/0x5af0 kernel/sched/core.c:6688
 __schedule_loop kernel/sched/core.c:6763 [inline]
 schedule+0xe9/0x270 kernel/sched/core.c:6778
 schedule_timeout+0x137/0x290 kernel/time/timer.c:2167
 rcu_gp_fqs_loop+0x1ec/0xb10 kernel/rcu/tree.c:1631
 rcu_gp_kthread+0x24b/0x380 kernel/rcu/tree.c:1830
 kthread+0x2c6/0x3a0 kernel/kthread.c:388
 ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
 </TASK>
rcu: Stack dump where RCU GP kthread last ran:
CPU: 1 PID: 17 Comm: rcu_preempt Not tainted 6.7.0-rc6-syzkaller-00157-g7c5e046bdcb2 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 11/17/2023
RIP: 0010:div_u64_rem include/linux/math64.h:29 [inline]
RIP: 0010:div_u64 include/linux/math64.h:130 [inline]
RIP: 0010:pie_calculate_probability+0x284/0x850 net/sched/sch_pie.c:345
Code: 89 c5 48 89 6c 24 38 e8 fa 47 e6 f8 47 8d 24 a4 31 d2 4c 89 ff 43 8d 0c 24 49 c1 ee 02 48 b8 ff ff ff ff ff ff ff 00 48 f7 f1 <48> 89 c5 48 89 c6 48 c1 eb 02 49 89 cc e8 da 42 e6 f8 49 39 ef 73
RSP: 0018:ffffc900001f0bb8 EFLAGS: 00000207
RAX: 0000068db8bac710 RBX: 000000002af31dc4 RCX: 0000000000002710
RDX: 0000000000001eff RSI: ffffffff88a129d6 RDI: 0000000000000000
RBP: 00004189374bc6a7 R08: 0000000000000005 R09: 00000000000f4240
R10: 00000000000003e8 R11: 0000000000000002 R12: 0000000000001388
R13: 0000000000000004 R14: 000000000112e0be R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000555556c89ca8 CR3: 0000000078bae000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 fq_pie_timer+0x215/0x5a0 net/sched/sch_fq_pie.c:391
 call_timer_fn+0x193/0x590 kernel/time/timer.c:1700
 expire_timers kernel/time/timer.c:1751 [inline]
 __run_timers+0x764/0xb20 kernel/time/timer.c:2022
 run_timer_softirq+0x58/0xd0 kernel/time/timer.c:2035
 __do_softirq+0x21a/0x8de kernel/softirq.c:553
 invoke_softirq kernel/softirq.c:427 [inline]
 __irq_exit_rcu kernel/softirq.c:632 [inline]
 irq_exit_rcu+0xb7/0x120 kernel/softirq.c:644
 sysvec_apic_timer_interrupt+0x95/0xb0 arch/x86/kernel/apic/apic.c:1076
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:649
RIP: 0010:finish_task_switch.isra.0+0x223/0xca0 kernel/sched/core.c:5250
Code: 0a 00 00 44 8b 0d 35 8b be 0d 45 85 c9 0f 85 c0 01 00 00 48 89 df e8 cc f8 ff ff e8 57 47 33 00 fb 65 48 8b 1c 25 c0 bc 03 00 <48> 8d bb d8 15 00 00 48 b8 00 00 00 00 00 fc ff df 48 89 fa 48 c1
RSP: 0018:ffffc90000167a08 EFLAGS: 00000206
RAX: 000000000001e735 RBX: ffff888017e48000 RCX: 1ffffffff1e320a9
RDX: 0000000000000000 RSI: ffffffff8accaec0 RDI: ffffffff8b2efba0
RBP: ffffc90000167a50 R08: 0000000000000001 R09: 0000000000000001
R10: ffffffff8f1937d7 R11: 0000000000000000 R12: ffff8880b993d478
R13: ffff888026c53b80 R14: 0000000000000000 R15: ffff8880b993c700
 context_switch kernel/sched/core.c:5379 [inline]
 __schedule+0xee3/0x5af0 kernel/sched/core.c:6688
 __schedule_loop kernel/sched/core.c:6763 [inline]
 schedule+0xe9/0x270 kernel/sched/core.c:6778
 schedule_timeout+0x137/0x290 kernel/time/timer.c:2167
 rcu_gp_fqs_loop+0x1ec/0xb10 kernel/rcu/tree.c:1631
 rcu_gp_kthread+0x24b/0x380 kernel/rcu/tree.c:1830
 kthread+0x2c6/0x3a0 kernel/kthread.c:388
 ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
 </TASK>

Crashes (1):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2023/12/23 13:47 net 7c5e046bdcb2 fb427a07 .config console log report syz C [disk image] [vmlinux] [kernel image] ci-upstream-net-this-kasan-gce INFO: rcu detected stall in fq_pie_timer
* Struck through repros no longer work on HEAD.