[syzbot] [kasan?] [mm?] INFO: rcu detected stall in __run_timer_base

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: fe46a7dd189e Merge tag 'sound-6.9-rc1' of git://git.kernel..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=15c64113180000
kernel config: https://syzkaller.appspot.com/x/.config?x=fe78468a74fdc3b7
dashboard link: https://syzkaller.appspot.com/bug?extid=1acbadd9f48eeeacda29
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=16435913180000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=111600cb180000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/0f7abe4afac7/disk-fe46a7dd.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/82598d09246c/vmlinux-fe46a7dd.xz
kernel image: https://storage.googleapis.com/syzbot-assets/efa23788c875/bzImage-fe46a7dd.xz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+1acbad...@syzkaller.appspotmail.com

rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
rcu: 0-...!: (1 GPs behind) idle=d3cc/1/0x4000000000000000 softirq=6440/6443 fqs=2
rcu: (detected by 1, t=10506 jiffies, g=7245, q=210 ncpus=2)
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 5367 Comm: syz-executor780 Not tainted 6.8.0-syzkaller-08951-gfe46a7dd189e #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/27/2024
RIP: 0010:lockdep_recursion_finish kernel/locking/lockdep.c:467 [inline]
RIP: 0010:lock_release+0x5c0/0x9d0 kernel/locking/lockdep.c:5776
Code: 00 fc ff df 4c 8b 64 24 08 48 8b 5c 24 28 49 89 dd 4c 8d b4 24 90 00 00 00 48 c7 c7 60 d3 aa 8b e8 d5 9c 02 0a b8 ff ff ff ff <65> 0f c1 05 28 c5 90 7e 83 f8 01 0f 85 9a 00 00 00 4c 89 f3 48 c1
RSP: 0000:ffffc90000007720 EFLAGS: 00000082
RAX: 00000000ffffffff RBX: 0000000000000046 RCX: ffffc90000007703
RDX: 0000000000000001 RSI: ffffffff8baad360 RDI: ffffffff8bfed300
RBP: ffffc90000007860 R08: ffffffff8f873a6f R09: 1ffffffff1f0e74d
R10: dffffc0000000000 R11: fffffbfff1f0e74e R12: 1ffff92000000ef0
R13: 0000000000000046 R14: ffffc900000077b0 R15: dffffc0000000000
FS: 0000555594caf380(0000) GS:ffff8880b9400000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000020000600 CR3: 0000000023676000 CR4: 0000000000350ef0
Call Trace:
<NMI>
</NMI>
<IRQ>
rcu_lock_release include/linux/rcupdate.h:308 [inline]
rcu_read_unlock include/linux/rcupdate.h:783 [inline]
advance_sched+0xb37/0xca0 net/sched/sch_taprio.c:987
__run_hrtimer kernel/time/hrtimer.c:1692 [inline]
__hrtimer_run_queues+0x597/0xd00 kernel/time/hrtimer.c:1756
hrtimer_interrupt+0x396/0x990 kernel/time/hrtimer.c:1818
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1032 [inline]
__sysvec_apic_timer_interrupt+0x109/0x3a0 arch/x86/kernel/apic/apic.c:1049
instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1043 [inline]
sysvec_apic_timer_interrupt+0x52/0xc0 arch/x86/kernel/apic/apic.c:1043
asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702
RIP: 0010:__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:160 [inline]
RIP: 0010:_raw_spin_unlock_irq+0x29/0x50 kernel/locking/spinlock.c:202
Code: 90 f3 0f 1e fa 53 48 89 fb 48 83 c7 18 48 8b 74 24 08 e8 0a b4 f2 f5 48 89 df e8 c2 f3 f3 f5 e8 1d 19 1d f6 fb bf 01 00 00 00 <e8> 52 e0 e5 f5 65 8b 05 a3 c4 84 74 85 c0 74 06 5b e9 71 40 00 00
RSP: 0000:ffffc90000007cb0 EFLAGS: 00000282
RAX: 49e89c1a0716e600 RBX: ffff8880b942a740 RCX: ffffffff81720c2a
RDX: dffffc0000000000 RSI: ffffffff8baac1e0 RDI: 0000000000000001
RBP: ffffc90000007e10 R08: ffffffff92ce5537 R09: 1ffffffff259caa6
R10: dffffc0000000000 R11: fffffbfff259caa7 R12: ffff8880b942a788
R13: ffffc90000007d60 R14: dffffc0000000000 R15: 00000000ffffdaa5
__run_timer_base+0x1c0/0x8e0 kernel/time/timer.c:2420
run_timer_base kernel/time/timer.c:2428 [inline]
run_timer_softirq+0xb7/0x170 kernel/time/timer.c:2438
__do_softirq+0x2be/0x943 kernel/softirq.c:554
invoke_softirq kernel/softirq.c:428 [inline]
__irq_exit_rcu+0xf2/0x1c0 kernel/softirq.c:633
irq_exit_rcu+0x9/0x30 kernel/softirq.c:645
instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1043 [inline]
sysvec_apic_timer_interrupt+0xa6/0xc0 arch/x86/kernel/apic/apic.c:1043
</IRQ>
<TASK>
asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702
RIP: 0010:srso_safe_ret+0x0/0x20 arch/x86/lib/retpoline.S:208
Code: cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc 48 b8 <48> 8d 64 24 08 c3 cc cc 0f ae e8 e8 f0 ff ff ff 0f 0b 66 2e 0f 1f
RSP: 0000:ffffc90004907030 EFLAGS: 00000293
RAX: ffffffff814095ec RBX: 0000000000000000 RCX: ffff888028fe0000
RDX: 0000000000000000 RSI: ffffffff8140c1eb RDI: ffffffff8140c035
RBP: 1ffff92000920e30 R08: ffffffff81409480 R09: 0000000000000000
R10: ffffc90004907180 R11: fffff52000920e3c R12: ffffffff8f9755b0
R13: dffffc0000000000 R14: 1ffff92000920e30 R15: ffffffff9008ea3e
srso_return_thunk+0x5/0x5f arch/x86/lib/retpoline.S:222
unwind_next_frame+0x67c/0x2a00 arch/x86/kernel/unwind_orc.c:495
__unwind_start+0x641/0x7c0 arch/x86/kernel/unwind_orc.c:760
unwind_start arch/x86/include/asm/unwind.h:64 [inline]
arch_stack_walk+0x103/0x1b0 arch/x86/kernel/stacktrace.c:24
stack_trace_save+0x118/0x1d0 kernel/stacktrace.c:122
save_stack+0xfb/0x1f0 mm/page_owner.c:129
__set_page_owner+0x29/0x380 mm/page_owner.c:195
set_page_owner include/linux/page_owner.h:31 [inline]
post_alloc_hook+0x1ea/0x210 mm/page_alloc.c:1533
prep_new_page mm/page_alloc.c:1540 [inline]
get_page_from_freelist+0x33ea/0x3580 mm/page_alloc.c:3311
__alloc_pages+0x256/0x680 mm/page_alloc.c:4569
alloc_pages_mpol+0x3de/0x650 mm/mempolicy.c:2133
pagetable_alloc include/linux/mm.h:2842 [inline]
__pud_alloc_one include/asm-generic/pgalloc.h:169 [inline]
pud_alloc_one include/asm-generic/pgalloc.h:189 [inline]
__pud_alloc+0x93/0x4b0 mm/memory.c:5692
pud_alloc include/linux/mm.h:2799 [inline]
__handle_mm_fault+0x4472/0x72d0 mm/memory.c:5236
handle_mm_fault+0x3c2/0x8a0 mm/memory.c:5470
do_user_addr_fault arch/x86/mm/fault.c:1413 [inline]
handle_page_fault arch/x86/mm/fault.c:1505 [inline]
exc_page_fault+0x2a8/0x890 arch/x86/mm/fault.c:1563
asm_exc_page_fault+0x26/0x30 arch/x86/include/asm/idtentry.h:623
RIP: 0033:0x7f37687f9bcc
Code: 00 00 e8 67 52 03 00 48 83 f8 ff 74 07 48 89 05 3a 15 0b 00 31 d2 b9 00 06 00 20 bf 10 00 00 00 48 b8 74 65 61 6d 30 00 00 00 <48> 89 04 25 00 06 00 20 31 c0 48 89 14 25 08 06 00 20 48 8b 35 0b
RSP: 002b:00007ffc3f74a370 EFLAGS: 00010246
RAX: 000000306d616574 RBX: 0000000000000000 RCX: 0000000020000600
RDX: 0000000000000000 RSI: 0000000800000003 RDI: 0000000000000010
RBP: 00000000000f4240 R08: 0000000000000000 R09: 0000000100000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffc3f74a3c0
R13: 000000000003239a R14: 00007ffc3f74a38c R15: 0000000000000003
</TASK>
INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 4.146 msecs
rcu: rcu_preempt kthread starved for 10495 jiffies! g7245 f0x0 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:26256 pid:16 tgid:16 ppid:2 flags:0x00004000
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5409 [inline]
__schedule+0x17d3/0x4a20 kernel/sched/core.c:6736
__schedule_loop kernel/sched/core.c:6813 [inline]
schedule+0x14b/0x320 kernel/sched/core.c:6828
schedule_timeout+0x1be/0x310 kernel/time/timer.c:2572
rcu_gp_fqs_loop+0x2df/0x1370 kernel/rcu/tree.c:1663
rcu_gp_kthread+0xa7/0x3b0 kernel/rcu/tree.c:1862
kthread+0x2f2/0x390 kernel/kthread.c:388
ret_from_fork+0x4d/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:243
</TASK>
rcu: Stack dump where RCU GP kthread last ran:
CPU: 1 PID: 61 Comm: kworker/u8:4 Not tainted 6.8.0-syzkaller-08951-gfe46a7dd189e #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/27/2024
Workqueue: events_unbound toggle_allocation_gate
RIP: 0010:csd_lock_wait kernel/smp.c:311 [inline]
RIP: 0010:smp_call_function_many_cond+0x1855/0x2960 kernel/smp.c:855
Code: 89 e6 83 e6 01 31 ff e8 d9 d5 0b 00 41 83 e4 01 49 bc 00 00 00 00 00 fc ff df 75 07 e8 84 d1 0b 00 eb 38 f3 90 42 0f b6 04 23 <84> c0 75 11 41 f7 45 00 01 00 00 00 74 1e e8 68 d1 0b 00 eb e4 44
RSP: 0018:ffffc900015c76e0 EFLAGS: 00000293
RAX: 0000000000000000 RBX: 1ffff11017288c0d RCX: ffff88801aadbc00
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000000
RBP: ffffc900015c78e0 R08: ffffffff818923b7 R09: 1ffffffff259caa0
R10: dffffc0000000000 R11: fffffbfff259caa1 R12: dffffc0000000000
R13: ffff8880b9446068 R14: ffff8880b953f480 R15: 0000000000000000
FS: 0000000000000000(0000) GS:ffff8880b9500000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000555594cafca8 CR3: 000000000df32000 CR4: 0000000000350ef0
Call Trace:
<IRQ>
</IRQ>
<TASK>
on_each_cpu_cond_mask+0x3f/0x80 kernel/smp.c:1023
on_each_cpu include/linux/smp.h:71 [inline]
text_poke_sync arch/x86/kernel/alternative.c:2086 [inline]
text_poke_bp_batch+0x352/0xb30 arch/x86/kernel/alternative.c:2296
text_poke_flush arch/x86/kernel/alternative.c:2487 [inline]
text_poke_finish+0x30/0x50 arch/x86/kernel/alternative.c:2494
arch_jump_label_transform_apply+0x1c/0x30 arch/x86/kernel/jump_label.c:146
static_key_enable_cpuslocked+0x136/0x260 kernel/jump_label.c:205
static_key_enable+0x1a/0x20 kernel/jump_label.c:218
toggle_allocation_gate+0xb5/0x250 mm/kfence/core.c:826
process_one_work kernel/workqueue.c:3254 [inline]
process_scheduled_works+0xa02/0x1770 kernel/workqueue.c:3335
worker_thread+0x86d/0xd70 kernel/workqueue.c:3416
kthread+0x2f2/0x390 kernel/kthread.c:388
ret_from_fork+0x4d/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:243
</TASK>


---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

If the report is already addressed, let syzbot know by replying with:
#syz fix: exact-commit-title

If you want syzbot to run the reproducer, reply with:
#syz test: git://repo/address.git branch-or-commit-hash
If you attach or paste a git patch, syzbot will apply it before testing.

If you want to overwrite report's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

If the report is a duplicate of another one, reply with:
#syz dup: exact-subject-of-another-report

If you want to undo deduplication, reply with:
#syz undup

[Hillf Danton]

On Sat, 13 Apr 2024 19:04:34 -0700

> syzbot found the following issue on:
>
> HEAD commit: fe46a7dd189e Merge tag 'sound-6.9-rc1' of git://git.kernel..
> git tree: upstream

> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=111600cb180000

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git fe46a7dd189e

--- x/net/sched/sch_taprio.c
+++ y/net/sched/sch_taprio.c
@@ -980,7 +980,9 @@ first_run:
rcu_assign_pointer(q->current_entry, next);
spin_unlock(&q->current_entry_lock);

- hrtimer_set_expires(&q->advance_timer, end_time);
+ hrtimer_set_expires(&q->advance_timer,
+ ktime_add(timer->base->get_time(),
+ ns_to_ktime(NSEC_PER_USEC *200)));

rcu_read_lock();
__netif_schedule(sch);
--

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+1acbad...@syzkaller.appspotmail.com

Tested on:

commit: fe46a7dd Merge tag 'sound-6.9-rc1' of git://git.kernel..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
console output: https://syzkaller.appspot.com/x/log.txt?x=13cea36d180000

kernel config: https://syzkaller.appspot.com/x/.config?x=fe78468a74fdc3b7
dashboard link: https://syzkaller.appspot.com/bug?extid=1acbadd9f48eeeacda29
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40

patch: https://syzkaller.appspot.com/x/patch.diff?x=11872f4d180000

Note: testing is done by a robot and is best-effort only.

[Yun Lu]

Syzbot reported the issues which rcu_preempt detected stalls on CPUs, and
the Call Trace shows that CPU is stuck on taprio hrtimer [1] [2].

rcu_lock_release include/linux/rcupdate.h:308 [inline]
rcu_read_unlock include/linux/rcupdate.h:783 [inline]
advance_sched+0xb37/0xca0 net/sched/sch_taprio.c:987
__run_hrtimer kernel/time/hrtimer.c:1692 [inline]
__hrtimer_run_queues+0x597/0xd00 kernel/time/hrtimer.c:1756
hrtimer_interrupt+0x396/0x990 kernel/time/hrtimer.c:1818
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1032 [inline]
__sysvec_apic_timer_interrupt+0x109/0x3a0 arch/x86/kernel/apic/apic.c:1049
instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1043 [inline]
sysvec_apic_timer_interrupt+0x52/0xc0 arch/x86/kernel/apic/apic.c:1043
asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702

......

Assuming the clockid of hrtimer is set to REALTIME and hrtimer is started,
the system time is then adjusted by a significant value backwards, and this
adjustment is not taken into account in the advance_sched function, which
still calculating the hrtimer expires based on the previous end_time.

This will result in the hrtimer expires being much smaller than the current
system time. Consequently, this hrtimer keeps getting inserted as the first
node in the timerqueue, causing the CPU to enter an infinite loop in the
__hrtimer_run_queues function, getting stuck and unable to exit or respond
to any interrupts.

To address this, when calculating the start time of the hrtimer, retain a
record of the offset between the current time corresponding to clockid and
the monotonic time. Subsequently, when setting the hrtimer expires, check
if this offset has changed. If it has, the hrtimer expires should be
adjusted accordingly by adding this difference offset value.

[1] https://lore.kernel.org/all/00000000000022...@google.com/
[2] https://lore.kernel.org/all/000000000000d9...@google.com/

Signed-off-by: Yun Lu <lu...@kylinos.cn>
Reported-by: syzbot+1acbad...@syzkaller.appspotmail.com
---
net/sched/sch_taprio.c | 20 ++++++++++++++++++++
1 file changed, 20 insertions(+)

diff --git a/net/sched/sch_taprio.c b/net/sched/sch_taprio.c
index a0d54b422186..360778f65d9e 100644
--- a/net/sched/sch_taprio.c
+++ b/net/sched/sch_taprio.c
@@ -104,6 +104,7 @@ struct taprio_sched {
u32 max_sdu[TC_MAX_QUEUE]; /* save info from the user */
u32 fp[TC_QOPT_MAX_QUEUE]; /* only for dump and offloading */
u32 txtime_delay;
+ ktime_t offset;
};

struct __tc_taprio_qopt_offload {
@@ -170,6 +171,13 @@ static ktime_t sched_base_time(const struct sched_gate_list *sched)
return ns_to_ktime(sched->base_time);
}

+static ktime_t taprio_get_offset(enum tk_offsets tk_offset)
+{
+ ktime_t time = ktime_get();
+
+ return ktime_sub_ns(ktime_mono_to_any(time, tk_offset), time);
+}
+
static ktime_t taprio_mono_to_any(const struct taprio_sched *q, ktime_t mono)
{
/* This pairs with WRITE_ONCE() in taprio_parse_clockid() */
@@ -918,6 +926,8 @@ static enum hrtimer_restart advance_sched(struct hrtimer *timer)
int num_tc = netdev_get_num_tc(dev);
struct sched_entry *entry, *next;
struct Qdisc *sch = q->root;
+ enum tk_offsets tk_offset = READ_ONCE(q->tk_offset);
+ ktime_t now_offset = taprio_get_offset(tk_offset);
ktime_t end_time;
int tc;

@@ -957,6 +967,14 @@ static enum hrtimer_restart advance_sched(struct hrtimer *timer)
end_time = ktime_add_ns(entry->end_time, next->interval);
end_time = min_t(ktime_t, end_time, oper->cycle_end_time);

+ if (q->offset != now_offset) {
+ ktime_t diff = ktime_sub_ns(now_offset, q->offset);
+
+ end_time = ktime_add_ns(end_time, diff);
+ oper->cycle_end_time = ktime_add_ns(oper->cycle_end_time, diff);
+ q->offset = now_offset;
+ }
+
for (tc = 0; tc < num_tc; tc++) {
if (next->gate_duration[tc] == oper->cycle_time)
next->gate_close_time[tc] = KTIME_MAX;
@@ -1205,11 +1223,13 @@ static int taprio_get_start_time(struct Qdisc *sch,
ktime_t *start)
{
struct taprio_sched *q = qdisc_priv(sch);
+ enum tk_offsets tk_offset = READ_ONCE(q->tk_offset);
ktime_t now, base, cycle;
s64 n;

base = sched_base_time(sched);
now = taprio_get_time(q);
+ q->offset = taprio_get_offset(tk_offset);

if (ktime_after(base, now)) {
*start = base;
--
2.34.1

[Yun Lu]

Syzbot reported the issues which rcu_preempt detected stalls on CPUs, and
the Call Trace shows that CPU is stuck on taprio hrtimer [1] [2].

rcu_lock_release include/linux/rcupdate.h:308 [inline]
rcu_read_unlock include/linux/rcupdate.h:783 [inline]
advance_sched+0xb37/0xca0 net/sched/sch_taprio.c:987
__run_hrtimer kernel/time/hrtimer.c:1692 [inline]
__hrtimer_run_queues+0x597/0xd00 kernel/time/hrtimer.c:1756
hrtimer_interrupt+0x396/0x990 kernel/time/hrtimer.c:1818
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1032 [inline]
__sysvec_apic_timer_interrupt+0x109/0x3a0 arch/x86/kernel/apic/apic.c:1049
instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1043 [inline]
sysvec_apic_timer_interrupt+0x52/0xc0 arch/x86/kernel/apic/apic.c:1043
asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702

[Yun Lu]

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
UBSAN: array-index-out-of-bounds in ktime_mono_to_any

------------[ cut here ]------------
UBSAN: array-index-out-of-bounds in kernel/time/timekeeping.c:927:20
index 3 is out of range for type 'ktime_t *[3]' (aka 'long long *[3]')
CPU: 0 PID: 5514 Comm: syz-executor.0 Not tainted 6.9.0-rc6-syzkaller-00131-gf03359bca01b-dirty #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/27/2024

Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:88 [inline]
dump_stack_lvl+0x241/0x360 lib/dump_stack.c:114
ubsan_epilogue lib/ubsan.c:231 [inline]
__ubsan_handle_out_of_bounds+0x121/0x150 lib/ubsan.c:429
ktime_mono_to_any+0xf7/0x100 kernel/time/timekeeping.c:927
taprio_get_offset net/sched/sch_taprio.c:178 [inline]
taprio_get_start_time+0xf6/0x2a0 net/sched/sch_taprio.c:1232
taprio_change+0x30c5/0x42d0 net/sched/sch_taprio.c:1963
taprio_init+0x9da/0xc80 net/sched/sch_taprio.c:2135
qdisc_create+0x9d6/0x1190 net/sched/sch_api.c:1355
tc_modify_qdisc+0xa26/0x1e40 net/sched/sch_api.c:1776
rtnetlink_rcv_msg+0x89d/0x10d0 net/core/rtnetlink.c:6595
netlink_rcv_skb+0x1e5/0x430 net/netlink/af_netlink.c:2559
netlink_unicast_kernel net/netlink/af_netlink.c:1335 [inline]
netlink_unicast+0x7ec/0x980 net/netlink/af_netlink.c:1361
netlink_sendmsg+0x8e1/0xcb0 net/netlink/af_netlink.c:1905
sock_sendmsg_nosec net/socket.c:730 [inline]
__sock_sendmsg+0x223/0x270 net/socket.c:745
____sys_sendmsg+0x525/0x7d0 net/socket.c:2584
___sys_sendmsg net/socket.c:2638 [inline]
__sys_sendmsg+0x2b0/0x3a0 net/socket.c:2667
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xf5/0x240 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7fca4dc7de69
Code: 28 00 00 00 75 05 48 83 c4 28 c3 e8 e1 20 00 00 90 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 c7 c1 b0 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007fca4e9720c8 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
RAX: ffffffffffffffda RBX: 00007fca4ddabf80 RCX: 00007fca4dc7de69
RDX: 0000000000000000 RSI: 00000000200007c0 RDI: 0000000000000004
RBP: 00007fca4dcca47a R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000000b R14: 00007fca4ddabf80 R15: 00007fffc66d5928
</TASK>
---[ end trace ]---


Tested on:

commit: f03359bc Merge tag 'for-6.9-rc6-tag' of git://git.kern..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
console output: https://syzkaller.appspot.com/x/log.txt?x=17aef62f180000
kernel config: https://syzkaller.appspot.com/x/.config?x=38cdad974684e704

dashboard link: https://syzkaller.appspot.com/bug?extid=1acbadd9f48eeeacda29
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40

patch: https://syzkaller.appspot.com/x/patch.diff?x=1665ecc0980000

[syzbot]

syzbot has bisected this issue to:

commit da71714e359b64bd7aab3bd56ec53f307f058133
Author: Jamal Hadi Salim <j...@mojatatu.com>
Date: Tue Aug 22 10:12:31 2023 +0000

net/sched: fix a qdisc modification with ambiguous command request

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=13b9b317180000
start commit: fe46a7dd189e Merge tag 'sound-6.9-rc1' of git://git.kernel..
git tree: upstream
final oops: https://syzkaller.appspot.com/x/report.txt?x=1079b317180000
console output: https://syzkaller.appspot.com/x/log.txt?x=17b9b317180000

kernel config: https://syzkaller.appspot.com/x/.config?x=fe78468a74fdc3b7
dashboard link: https://syzkaller.appspot.com/bug?extid=1acbadd9f48eeeacda29

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=16435913180000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=111600cb180000

Reported-by: syzbot+1acbad...@syzkaller.appspotmail.com
Fixes: da71714e359b ("net/sched: fix a qdisc modification with ambiguous command request")

For information about bisection process see: https://goo.gl/tpsmEJ#bisection

[Jakub Kicinski]

On Fri, 3 May 2024 17:18:44 +0800 Yun Lu wrote:
> #syz test https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

Why are you CCing netdev@ on this? 🤔️

[Yun Lu]

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

Signed-off-by: Yun Lu <lu...@kylinos.cn>
---
net/sched/sch_taprio.c | 24 ++++++++++++++++++++++++
1 file changed, 24 insertions(+)

diff --git a/net/sched/sch_taprio.c b/net/sched/sch_taprio.c
index a0d54b422186..2ff8d34bdbac 100644

--- a/net/sched/sch_taprio.c
+++ b/net/sched/sch_taprio.c
@@ -104,6 +104,7 @@ struct taprio_sched {
u32 max_sdu[TC_MAX_QUEUE]; /* save info from the user */
u32 fp[TC_QOPT_MAX_QUEUE]; /* only for dump and offloading */
u32 txtime_delay;
+ ktime_t offset;
};

struct __tc_taprio_qopt_offload {

@@ -170,6 +171,19 @@ static ktime_t sched_base_time(const struct sched_gate_list *sched)
return ns_to_ktime(sched->base_time);
}

+static ktime_t taprio_get_offset(const struct taprio_sched *q)
+{

+ enum tk_offsets tk_offset = READ_ONCE(q->tk_offset);

+ ktime_t time = ktime_get();
+

+ switch (tk_offset) {
+ case TK_OFFS_MAX:
+ return 0;
+ default:

+ return ktime_sub_ns(ktime_mono_to_any(time, tk_offset), time);
+ }
+}
+
static ktime_t taprio_mono_to_any(const struct taprio_sched *q, ktime_t mono)
{
/* This pairs with WRITE_ONCE() in taprio_parse_clockid() */

@@ -918,6 +932,7 @@ static enum hrtimer_restart advance_sched(struct hrtimer *timer)

int num_tc = netdev_get_num_tc(dev);
struct sched_entry *entry, *next;
struct Qdisc *sch = q->root;

+ ktime_t now_offset = taprio_get_offset(q);
ktime_t end_time;
int tc;

@@ -957,6 +972,14 @@ static enum hrtimer_restart advance_sched(struct hrtimer *timer)

end_time = ktime_add_ns(entry->end_time, next->interval);
end_time = min_t(ktime_t, end_time, oper->cycle_end_time);

+ if (q->offset != now_offset) {
+ ktime_t diff = ktime_sub_ns(now_offset, q->offset);
+
+ end_time = ktime_add_ns(end_time, diff);
+ oper->cycle_end_time = ktime_add_ns(oper->cycle_end_time, diff);
+ q->offset = now_offset;
+ }
+
for (tc = 0; tc < num_tc; tc++) {
if (next->gate_duration[tc] == oper->cycle_time)
next->gate_close_time[tc] = KTIME_MAX;

@@ -1210,6 +1233,7 @@ static int taprio_get_start_time(struct Qdisc *sch,

base = sched_base_time(sched);
now = taprio_get_time(q);

+ q->offset = taprio_get_offset(q);

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:

INFO: rcu detected stall in sys_mkdirat

rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 1-...D } 2672 jiffies s: 2029 root: 0x2/.
rcu: blocking rcu_node structures (internal RCU debug):
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 5458 Comm: syz-executor.0 Not tainted 6.9.0-rc7-syzkaller-gdd5a440a31fa-dirty #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/27/2024

RIP: 0010:lockdep_enabled kernel/locking/lockdep.c:122 [inline]
RIP: 0010:lock_release+0x125/0x9f0 kernel/locking/lockdep.c:5767
Code: 7e 85 c0 0f 85 23 05 00 00 65 48 8b 04 25 c0 d3 03 00 48 89 44 24 18 48 8d 98 d4 0a 00 00 48 89 d8 48 c1 e8 03 42 0f b6 04 38 <84> c0 0f 85 d8 05 00 00 83 3b 00 0f 85 f1 04 00 00 4c 8d b4 24 b0
RSP: 0018:ffffc90000a08a20 EFLAGS: 00000017
RAX: 0000000000000000 RBX: ffff888026abe4d4 RCX: ffffffff81728e30
RDX: 0000000000000000 RSI: ffffffff8c1f89c0 RDI: ffffffff8c1f8980
RBP: ffffc90000a08b50 R08: ffffffff8fa9faef R09: 1ffffffff1f53f5d
R10: dffffc0000000000 R11: fffffbfff1f53f5e R12: 1ffff92000141150
R13: ffffffff84b6f924 R14: ffffc90000a08b80 R15: dffffc0000000000
FS: 00005555763c6480(0000) GS:ffff8880b9500000(0000) knlGS:0000000000000000

CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

CR2: 00007fffe1c6dbf8 CR3: 0000000022fe4000 CR4: 0000000000350ef0

Call Trace:
<NMI>
</NMI>
<IRQ>

__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:149 [inline]
_raw_spin_unlock_irqrestore+0x79/0x140 kernel/locking/spinlock.c:194
debug_object_activate+0x3e4/0x510 lib/debugobjects.c:726
debug_hrtimer_activate kernel/time/hrtimer.c:423 [inline]
debug_activate kernel/time/hrtimer.c:478 [inline]
enqueue_hrtimer+0x30/0x3c0 kernel/time/hrtimer.c:1090
__run_hrtimer kernel/time/hrtimer.c:1709 [inline]
__hrtimer_run_queues+0x6d5/0xd50 kernel/time/hrtimer.c:1756

hrtimer_interrupt+0x396/0x990 kernel/time/hrtimer.c:1818
local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1032 [inline]

__sysvec_apic_timer_interrupt+0x112/0x3f0 arch/x86/kernel/apic/apic.c:1049
instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1043 [inline]
sysvec_apic_timer_interrupt+0xa1/0xc0 arch/x86/kernel/apic/apic.c:1043

</IRQ>
<TASK>
asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702

RIP: 0010:kmem_cache_free+0x15/0x2c0 mm/slub.c:4339
Code: 00 00 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 55 41 57 41 56 41 55 41 54 53 48 83 ec 10 48 89 f3 <65> 48 8b 04 25 28 00 00 00 48 89 44 24 08 e8 a8 02 00 00 48 85 c0
RSP: 0018:ffffc900042972b8 EFLAGS: 00000286
RAX: ffffffff825d0aa6 RBX: ffff88807794e820 RCX: ffff888026abda00
RDX: 0000000000000000 RSI: ffff88807794e820 RDI: ffff8880193dac80
RBP: ffffc900042974b0 R08: ffffffff825d0a81 R09: 1ffffffff1f53f5d
R10: dffffc0000000000 R11: fffffbfff1f53f5e R12: ffff88802f56c000
R13: ffff88807794e8a0 R14: ffffc90004297720 R15: 0000000000000001
ext4_mb_new_blocks+0x2ab4/0x4bf0 fs/ext4/mballoc.c:6250
ext4_ext_map_blocks+0x1c74/0x77b0 fs/ext4/extents.c:4317
ext4_map_blocks+0xa5e/0x1d20 fs/ext4/inode.c:623
ext4_getblk+0x1fa/0x850 fs/ext4/inode.c:833
ext4_bread+0x2e/0x180 fs/ext4/inode.c:889
ext4_append+0x327/0x5c0 fs/ext4/namei.c:83
ext4_init_new_dir+0x33e/0xa30 fs/ext4/namei.c:2977
ext4_mkdir+0x4f7/0xcf0 fs/ext4/namei.c:3023
vfs_mkdir+0x2fb/0x4b0 fs/namei.c:4123
do_mkdirat+0x264/0x3a0 fs/namei.c:4146
__do_sys_mkdirat fs/namei.c:4161 [inline]
__se_sys_mkdirat fs/namei.c:4159 [inline]
__x64_sys_mkdirat+0x89/0xa0 fs/namei.c:4159

do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xf5/0x240 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f

RIP: 0033:0x7f0aef87c967
Code: 73 01 c3 48 c7 c1 b0 ff ff ff f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 02 01 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 b0 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007fffe1c6f498 EFLAGS: 00000202 ORIG_RAX: 0000000000000102
RAX: ffffffffffffffda RBX: 00007fffe1c6f520 RCX: 00007f0aef87c967
RDX: 00000000000001ff RSI: 00007fffe1c6f520 RDI: 00000000ffffff9c
RBP: 00007fffe1c6f4fc R08: 0000000000000004 R09: 00007fffe1c6f236
R10: 0000000000000000 R11: 0000000000000202 R12: 0000000000000032
R13: 000000000001cfb4 R14: 000000000001cfab R15: 0000000000000004
</TASK>


Tested on:

commit: dd5a440a Linux 6.9-rc7

git tree: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

console output: https://syzkaller.appspot.com/x/log.txt?x=1298931f180000
kernel config: https://syzkaller.appspot.com/x/.config?x=448b220a4abc599a

dashboard link: https://syzkaller.appspot.com/bug?extid=1acbadd9f48eeeacda29
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40

patch: https://syzkaller.appspot.com/x/patch.diff?x=125a2ca8980000

[Yun Lu]

Hello,

Indeed, the taprio hrtimer does cause CPU stuck in certain specific scenarios,
and this patch indirectly confirms it.

However, it seems this patch isn't the final solution?

On my testing machine, after starting Taprio hrtimer and then adjusting the
system time backward, it can be observed that the taprio hrtimer indeed gets stuck
in an infinite loop through tracing. And, the patch below can effectively resolve
this issue, but it doesn't work for syzbot's tests.

https://lore.kernel.org/all/20240506023617....@kylinos.cn/

Are there any better suggestions from others regarding the resolution of this CPU stuck issue?