syzbot


BUG: soft lockup in call_timer_fn (2)

Status: moderation: reported on 2024/10/16 05:24
Subsystems: trace
[Documentation on labels]
Reported-by: syzbot+8e092a384bb9a6e28da0@syzkaller.appspotmail.com
First crash: 5d22h, last: 5d22h
Similar bugs (7)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
linux-4.14 BUG: soft lockup in call_timer_fn 1 1741d 1741d 0/1 auto-closed as invalid on 2020/05/10 07:38
upstream BUG: soft lockup in call_timer_fn mm net 19 79d 122d 0/28 auto-obsoleted due to no activity on 2024/10/08 10:43
linux-4.19 BUG: soft lockup in call_timer_fn C error 31 593d 1196d 0/1 upstream: reported C repro on 2021/07/10 02:48
upstream INFO: rcu detected stall in call_timer_fn (2) kernel C done error 47 1003d 1859d 0/28 closed as invalid on 2022/02/08 10:46
linux-6.1 INFO: rcu detected stall in call_timer_fn 2 5d01h 76d 0/3 upstream: reported on 2024/08/02 13:31
upstream INFO: rcu detected stall in call_timer_fn (4) mm 1 260d 260d 0/28 auto-obsoleted due to no activity on 2024/03/31 10:44
upstream INFO: rcu detected stall in call_timer_fn (3) kernel 3 742d 757d 0/28 auto-obsoleted due to no activity on 2023/01/12 18:45

Sample crash report:
watchdog: BUG: soft lockup - CPU#1 stuck for 143s! [syz.1.855:8027]
Modules linked in:
irq event stamp: 11837755
hardirqs last  enabled at (11837754): [<ffffffff8bc56683>] irqentry_exit+0x63/0x90 kernel/entry/common.c:357
hardirqs last disabled at (11837755): [<ffffffff8bc5422e>] sysvec_apic_timer_interrupt+0xe/0xc0 arch/x86/kernel/apic/apic.c:1037
softirqs last  enabled at (10258530): [<ffffffff81579384>] __do_softirq kernel/softirq.c:588 [inline]
softirqs last  enabled at (10258530): [<ffffffff81579384>] invoke_softirq kernel/softirq.c:428 [inline]
softirqs last  enabled at (10258530): [<ffffffff81579384>] __irq_exit_rcu+0xf4/0x1c0 kernel/softirq.c:637
softirqs last disabled at (10258533): [<ffffffff81579384>] __do_softirq kernel/softirq.c:588 [inline]
softirqs last disabled at (10258533): [<ffffffff81579384>] invoke_softirq kernel/softirq.c:428 [inline]
softirqs last disabled at (10258533): [<ffffffff81579384>] __irq_exit_rcu+0xf4/0x1c0 kernel/softirq.c:637
CPU: 1 UID: 0 PID: 8027 Comm: syz.1.855 Not tainted 6.12.0-rc1-syzkaller-00174-g82370ed5ade5 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
RIP: 0010:strlen+0x31/0x70 lib/string.c:402
Code: 56 41 54 53 49 89 fe 48 c7 c0 ff ff ff ff 49 bf 00 00 00 00 00 fc ff df 48 89 fb 49 89 c4 48 89 d8 48 c1 e8 03 42 0f b6 04 38 <84> c0 75 12 48 ff c3 49 8d 44 24 01 43 80 7c 26 01 00 75 dd eb 13
RSP: 0018:ffffc90000a18938 EFLAGS: 00000a06
RAX: 0000000000000000 RBX: ffffffff8d1d8120 RCX: 0000000000a18a03
RDX: ffffffff8181ecc0 RSI: ffffc90000a18c00 RDI: ffffffff8d1d8120
RBP: ffffc90000a18a70 R08: ffffffff901ce46f R09: 1ffffffff2039c8d
R10: dffffc0000000000 R11: fffffbfff2039c8e R12: ffffffffffffffff
R13: ffffffff8181ecc0 R14: ffffffff8d1d8120 R15: dffffc0000000000
FS:  00007f7ed156c6c0(0000) GS:ffff8880b8700000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000000 CR3: 0000000043f64000 CR4: 00000000003526f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 trace_event_get_offsets_lock include/trace/events/lock.h:50 [inline]
 perf_trace_lock+0x10a/0x490 include/trace/events/lock.h:50
 trace_lock_release include/trace/events/lock.h:69 [inline]
 lock_release+0x9cc/0xa30 kernel/locking/lockdep.c:5836
 call_timer_fn+0x24a/0x650 kernel/time/timer.c:1797
 expire_timers kernel/time/timer.c:1845 [inline]
 __run_timers kernel/time/timer.c:2419 [inline]
 __run_timer_base+0x66a/0x8e0 kernel/time/timer.c:2430
NMI backtrace for cpu 1
CPU: 1 UID: 0 PID: 8027 Comm: syz.1.855 Not tainted 6.12.0-rc1-syzkaller-00174-g82370ed5ade5 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
RIP: 0010:asm_exc_int3+0x0/0x40 arch/x86/include/asm/idtentry.h:622
Code: e9 e5 08 00 00 0f 1f 44 00 00 f3 0f 1e fa 0f 01 ca fc 6a ff e8 91 07 00 00 48 89 c4 48 89 e7 e8 f6 f1 e4 ff e9 c1 08 00 00 90 <f3> 0f 1e fa 0f 01 ca fc 6a ff f6 44 24 10 03 75 18 ff 74 24 28 ff
RSP: 0018:ffffc90000a17d78 EFLAGS: 00000802
RAX: f2f2f200f1f1f1f1 RBX: ffffffff81745983 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff8e813360
RBP: ffffc90000a17ee8 R08: 0000000000000001 R09: 0000000000000000
R10: dffffc0000000000 R11: fffffbfff1d02661 R12: 1ffff92000142fbc
R13: dffffc0000000000 R14: 0000000000000000 R15: 0000000000000059
FS:  00007f7ed156c6c0(0000) GS:ffff8880b8700000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000000 CR3: 0000000043f64000 CR4: 00000000003526f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
RIP: 0010:arch_static_branch arch/x86/include/asm/jump_label.h:27 [inline]
RIP: 0010:static_key_false include/linux/jump_label.h:207 [inline]
RIP: 0010:trace_lock_acquire include/trace/events/lock.h:24 [inline]
RIP: 0010:lock_acquire+0xa5/0x550 kernel/locking/lockdep.c:5796
Code: f1 00 f2 f2 f2 4b 89 04 2c 43 c7 44 2c 09 f2 f2 f2 00 43 c7 44 2c 11 f3 f3 f3 f3 66 43 c7 44 2c 15 f3 f3 43 c6 44 2c 17 f3 cc <1f> 44 00 00 65 8b 05 5c 8b 93 7e 83 f8 08 0f 83 f4 02 00 00 89 c3
RSP: 0018:ffffc90000a17da0 EFLAGS: 00000802
 </IRQ>
 <TASK>
 </TASK>
 run_timer_base kernel/time/timer.c:2439 [inline]
 run_timer_softirq+0xb7/0x170 kernel/time/timer.c:2449
 handle_softirqs+0x2c5/0x980 kernel/softirq.c:554
 __do_softirq kernel/softirq.c:588 [inline]
 invoke_softirq kernel/softirq.c:428 [inline]
 __irq_exit_rcu+0xf4/0x1c0 kernel/softirq.c:637
 irq_exit_rcu+0x9/0x30 kernel/softirq.c:649
 instr_sysvec_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1037 [inline]
 sysvec_apic_timer_interrupt+0xa6/0xc0 arch/x86/kernel/apic/apic.c:1037
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:702
RIP: 0010:smp_call_function_many_cond+0x18a4/0x2ca0 kernel/smp.c:879
Code: 62 f6 0b 00 4c 8b 7c 24 20 4d 85 f6 75 11 e8 53 f6 0b 00 83 7c 24 18 00 75 16 e9 c6 0b 00 00 e8 42 f6 0b 00 fb 83 7c 24 18 00 <0f> 84 b5 0b 00 00 44 3b 7c 24 78 0f 83 aa 0b 00 00 4d 8d 75 08 4c
RSP: 0018:ffffc9000316f580 EFLAGS: 00000202
RAX: ffffffff8188ed2e RBX: 0000000000000000 RCX: 0000000000040000
RDX: ffffc9001611a000 RSI: 0000000000003b97 RDI: 0000000000003b98
RBP: ffffc9000316f780 R08: ffffffff8188ed00 R09: 1ffffffff2858b00
R10: dffffc0000000000 R11: fffffbfff2858b01 R12: dffffc0000000000
R13: ffff8880b873fc80 R14: 0000000000000200 R15: 0000000000000000
 on_each_cpu_cond_mask+0x3f/0x80 kernel/smp.c:1051
 on_each_cpu include/linux/smp.h:71 [inline]
 text_poke_sync arch/x86/kernel/alternative.c:2085 [inline]
 text_poke_bp_batch+0x352/0xb30 arch/x86/kernel/alternative.c:2295
 text_poke_flush arch/x86/kernel/alternative.c:2486 [inline]
 text_poke_finish+0x30/0x50 arch/x86/kernel/alternative.c:2493
 arch_jump_label_transform_apply+0x1c/0x30 arch/x86/kernel/jump_label.c:146
 static_key_enable_cpuslocked+0x136/0x260 kernel/jump_label.c:210
 static_key_enable+0x1a/0x20 kernel/jump_label.c:223
 tracepoint_add_func+0x953/0x9e0 kernel/tracepoint.c:361
 tracepoint_probe_register_prio kernel/tracepoint.c:511 [inline]
 tracepoint_probe_register+0x105/0x160 kernel/tracepoint.c:531
 perf_trace_event_reg kernel/trace/trace_event_perf.c:129 [inline]
 perf_trace_event_init+0x478/0x930 kernel/trace/trace_event_perf.c:202
 perf_trace_init+0x243/0x2e0 kernel/trace/trace_event_perf.c:226
 perf_tp_event_init+0x8d/0x110 kernel/events/core.c:10357
 perf_try_init_event+0x146/0x810 kernel/events/core.c:11891
 perf_init_event kernel/events/core.c:11977 [inline]
 perf_event_alloc+0x135f/0x2310 kernel/events/core.c:12259
 __do_sys_perf_event_open kernel/events/core.c:12766 [inline]
 __se_sys_perf_event_open+0xb1f/0x3870 kernel/events/core.c:12657
 do_syscall_x64 arch/x86/entry/common.c:52 [inline]
 do_syscall_64+0xf3/0x230 arch/x86/entry/common.c:83
 entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f7ed077dff9
Code: ff ff 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 c7 c1 a8 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007f7ed156c038 EFLAGS: 00000246 ORIG_RAX: 000000000000012a
RAX: ffffffffffffffda RBX: 00007f7ed0935f80 RCX: 00007f7ed077dff9
RDX: ffffffffffffffff RSI: 0000000000000000 RDI: 0000000020000200
RBP: 00007f7ed07f0296 R08: 0000000000000000 R09: 0000000000000000
R10: ffffffffffffffff R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: 00007f7ed0935f80 R15: 00007ffd57d0c608
 </TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 UID: 0 PID: 5312 Comm: kworker/0:6 Not tainted 6.12.0-rc1-syzkaller-00174-g82370ed5ade5 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
Workqueue: events drain_vmap_area_work
RIP: 0010:csd_lock_wait kernel/smp.c:340 [inline]
RIP: 0010:smp_call_function_many_cond+0x19f3/0x2ca0 kernel/smp.c:884
Code: 45 8b 65 00 44 89 e6 83 e6 01 31 ff e8 46 f9 0b 00 41 83 e4 01 49 bc 00 00 00 00 00 fc ff df 75 07 e8 f1 f4 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 d5 f4
RSP: 0018:ffffc90003dbf900 EFLAGS: 00000293
RAX: ffffffff8188ee9b RBX: 1ffff110170e8919 RCX: ffff88802e6d9e00
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000000
RBP: ffffc90003dbfaf0 R08: ffffffff8188ee6a R09: 1ffffffff2858b00
R10: dffffc0000000000 R11: fffffbfff2858b01 R12: dffffc0000000000
R13: ffff8880b87448c8 R14: ffff8880b863fc80 R15: 0000000000000001
FS:  0000000000000000(0000) GS:ffff8880b8600000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fa2bdfffffc CR3: 000000002790e000 CR4: 00000000003526f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
Call Trace:
 <NMI>
 </NMI>
 <TASK>
 on_each_cpu_cond_mask+0x3f/0x80 kernel/smp.c:1051
 __purge_vmap_area_lazy+0x458/0xae0 mm/vmalloc.c:2268
 drain_vmap_area_work+0x27/0x40 mm/vmalloc.c:2322
 process_one_work kernel/workqueue.c:3229 [inline]
 process_scheduled_works+0xa63/0x1850 kernel/workqueue.c:3310
 worker_thread+0x870/0xd30 kernel/workqueue.c:3391
 kthread+0x2f0/0x390 kernel/kthread.c:389
 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>

Crashes (1):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2024/10/12 05:14 bpf-next 82370ed5ade5 084d8178 .config console log report info [disk image] [vmlinux] [kernel image] ci-upstream-bpf-next-kasan-gce BUG: soft lockup in call_timer_fn
* Struck through repros no longer work on HEAD.