2024-04-29 18:47:10

by syzbot

[permalink] [raw]
Subject: [syzbot] [sound?] INFO: rcu detected stall in snd_timer_user_release (3)

Hello,

syzbot found the following issue on:

HEAD commit: e88c4cfcb7b8 Merge tag 'for-6.9-rc5-tag' of git://git.kern..
git tree: upstream
console+strace: https://syzkaller.appspot.com/x/log.txt?x=1343b727180000
kernel config: https://syzkaller.appspot.com/x/.config?x=98d5a8e00ed1044a
dashboard link: https://syzkaller.appspot.com/bug?extid=43120c2af6ca2938cc38
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=15aef608980000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1039c208980000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/f00739ef493d/disk-e88c4cfc.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/e5ab311a2b65/vmlinux-e88c4cfc.xz
kernel image: https://storage.googleapis.com/syzbot-assets/0d097344a5b6/bzImage-e88c4cfc.xz

Bisection is inconclusive: the issue happens on the oldest tested release.

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=12b6e6d8980000
final oops: https://syzkaller.appspot.com/x/report.txt?x=11b6e6d8980000
console output: https://syzkaller.appspot.com/x/log.txt?x=16b6e6d8980000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: [email protected]

rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
rcu: 1-...!: (1 GPs behind) idle=477c/1/0x4000000000000000 softirq=6170/6171 fqs=0
rcu: (detected by 0, t=10502 jiffies, g=7293, q=28 ncpus=2)
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 5111 Comm: syz-executor278 Not tainted 6.9.0-rc5-syzkaller-00042-ge88c4cfcb7b8 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/27/2024
RIP: 0010:get_bucket lib/debugobjects.c:492 [inline]
RIP: 0010:debug_object_activate+0x13a/0x510 lib/debugobjects.c:706
Code: 8b 43 fd 48 8b 44 24 18 48 89 84 24 80 00 00 00 45 31 e4 80 3d aa 57 f2 0a 00 0f 85 b7 02 00 00 e8 eb 03 00 00 4c 89 7c 24 10 <49> c1 ef 0c 48 b9 eb 83 b5 80 46 86 c8 61 49 0f af cf 48 c1 e9 2f
RSP: 0018:ffffc90000a08c00 EFLAGS: 00000046
RAX: a301fc934e8fa400 RBX: ffffc90000a08c70 RCX: ffffc90000a08903
RDX: 0000000000000003 RSI: ffffffff8bcaca20 RDI: ffffffff8c1f9760
RBP: ffffc90000a08d18 R08: ffffffff8fa8fdaf R09: 1ffffffff1f51fb5
R10: dffffc0000000000 R11: fffffbfff1f51fb6 R12: 0000000000000000
R13: 1ffff92000141188 R14: dffffc0000000000 R15: ffff88801aadbc88
FS: 0000000000000000(0000) GS:ffff8880b9500000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f2070b46d33 CR3: 000000000e134000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<NMI>
</NMI>
<IRQ>
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+0x110/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:__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:152 [inline]
RIP: 0010:_raw_spin_unlock_irqrestore+0xd8/0x140 kernel/locking/spinlock.c:194
Code: 9c 8f 44 24 20 42 80 3c 23 00 74 08 4c 89 f7 e8 2e bb 6f f6 f6 44 24 21 02 75 52 41 f7 c7 00 02 00 00 74 01 fb bf 01 00 00 00 <e8> b3 fe da f5 65 8b 05 24 2b 79 74 85 c0 74 43 48 c7 04 24 0e 36
RSP: 0018:ffffc900022ef940 EFLAGS: 00000206
RAX: a301fc934e8fa400 RBX: 1ffff9200045df2c RCX: ffffffff8172edda
RDX: dffffc0000000000 RSI: ffffffff8bcab8a0 RDI: 0000000000000001
RBP: ffffc900022ef9d0 R08: ffffffff92f34587 R09: 1ffffffff25e68b0
R10: dffffc0000000000 R11: fffffbfff25e68b1 R12: dffffc0000000000
R13: 1ffff9200045df28 R14: ffffc900022ef960 R15: 0000000000000246
spin_unlock_irqrestore include/linux/spinlock.h:406 [inline]
class_spinlock_irqsave_destructor include/linux/spinlock.h:574 [inline]
snd_timer_stop1+0x7e6/0x950 sound/core/timer.c:634
snd_timer_stop sound/core/timer.c:679 [inline]
snd_timer_close_locked+0x223/0x8d0 sound/core/timer.c:423
snd_timer_close sound/core/timer.c:464 [inline]
snd_timer_user_release+0x138/0x2e0 sound/core/timer.c:1468
__fput+0x429/0x8a0 fs/file_table.c:422
task_work_run+0x24f/0x310 kernel/task_work.c:180
exit_task_work include/linux/task_work.h:38 [inline]
do_exit+0xa1b/0x27e0 kernel/exit.c:878
do_group_exit+0x207/0x2c0 kernel/exit.c:1027
__do_sys_exit_group kernel/exit.c:1038 [inline]
__se_sys_exit_group kernel/exit.c:1036 [inline]
__x64_sys_exit_group+0x3f/0x40 kernel/exit.c:1036
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:0x7f2070b46db9
Code: Unable to access opcode bytes at 0x7f2070b46d8f.
RSP: 002b:00007ffdfb750b08 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f2070b46db9
RDX: 000000000000003c RSI: 00000000000000e7 RDI: 0000000000000000
RBP: 00007f2070bc12b0 R08: ffffffffffffffb8 R09: 00000000000000a0
R10: 00000000000000a0 R11: 0000000000000246 R12: 00007f2070bc12b0
R13: 0000000000000000 R14: 00007f2070bc1d20 R15: 00007f2070b17f50
</TASK>
INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.845 msecs
rcu: rcu_preempt kthread starved for 10502 jiffies! g7293 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x0 ->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:R running task stack:23704 pid:16 tgid:16 ppid:2 flags:0x00004000
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5409 [inline]
__schedule+0x17e8/0x4a50 kernel/sched/core.c:6746
__schedule_loop kernel/sched/core.c:6823 [inline]
schedule+0x14b/0x320 kernel/sched/core.c:6838
schedule_timeout+0x1be/0x310 kernel/time/timer.c:2582
rcu_gp_fqs_loop+0x2df/0x1370 kernel/rcu/tree.c:1663
rcu_gp_kthread+0xa7/0x3b0 kernel/rcu/tree.c:1862
kthread+0x2f0/0x390 kernel/kthread.c:388
ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
rcu: Stack dump where RCU GP kthread last ran:
CPU: 0 PID: 1106 Comm: kworker/u8:7 Not tainted 6.9.0-rc5-syzkaller-00042-ge88c4cfcb7b8 #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+0x1894/0x2a00 kernel/smp.c:855
Code: 45 8b 65 00 44 89 e6 83 e6 01 31 ff e8 15 db 0b 00 41 83 e4 01 49 bc 00 00 00 00 00 fc ff df 75 07 e8 c0 d6 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 a4 d6
RSP: 0018:ffffc90004d676e0 EFLAGS: 00000293
RAX: ffffffff818a2abc RBX: 1ffff110172a8869 RCX: ffff888022bb9e00
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000000
RBP: ffffc90004d678e0 R08: ffffffff818a2a8b R09: 1ffffffff25e68a0
R10: dffffc0000000000 R11: fffffbfff25e68a1 R12: dffffc0000000000
R13: ffff8880b9544348 R14: ffff8880b943f7c0 R15: 0000000000000001
FS: 0000000000000000(0000) GS:ffff8880b9400000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f2070b9101d CR3: 000000000e134000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
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+0xa10/0x17c0 kernel/workqueue.c:3335
worker_thread+0x86d/0xd70 kernel/workqueue.c:3416
kthread+0x2f0/0x390 kernel/kthread.c:388
ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</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 [email protected].

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
For information about bisection process see: https://goo.gl/tpsmEJ#bisection

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


2024-04-29 23:43:12

by Hillf Danton

[permalink] [raw]
Subject: Re: [syzbot] [sound?] INFO: rcu detected stall in snd_timer_user_release (3)

On Mon, 29 Apr 2024 11:46:30 -0700
> syzbot found the following issue on:
>
> HEAD commit: e88c4cfcb7b8 Merge tag 'for-6.9-rc5-tag' of git://git.kern..
> git tree: upstream
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1039c208980000

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

--- x/sound/core/hrtimer.c
+++ y/sound/core/hrtimer.c
@@ -51,7 +51,8 @@ static enum hrtimer_restart snd_hrtimer_

guard(spinlock)(&t->lock);
if (t->running) {
- hrtimer_add_expires_ns(hrt, t->sticks * resolution);
+ hrtimer_set_expires(hrt, ktime_add(hrt->base->get_time(),
+ ns_to_ktime(NSEC_PER_USEC *200)));
ret = HRTIMER_RESTART;
}

--

2024-04-30 00:21:11

by syzbot

[permalink] [raw]
Subject: Re: [syzbot] [sound?] INFO: rcu detected stall in snd_timer_user_release (3)

Hello,

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

Reported-and-tested-by: [email protected]

Tested on:

commit: e88c4cfc Merge tag 'for-6.9-rc5-tag' of git://git.kern..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
console output: https://syzkaller.appspot.com/x/log.txt?x=10a0ca40980000
kernel config: https://syzkaller.appspot.com/x/.config?x=98d5a8e00ed1044a
dashboard link: https://syzkaller.appspot.com/bug?extid=43120c2af6ca2938cc38
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=11eaa58b180000

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