Hi Jihong and perf experts, Greetings! There was "BUG: soft lockup in asm_sysvec_apic_timer_interrupt" in v6.11-rc4 mainline kernel by local syzkaller Intel internal kernel testing. Bisected and found first bad commit: " 15def34e2635 perf/core: Fix hardlockup failure caused by perf throttle " After reverted above commit on top of v6.11-rc4 mainline kernel, this issue was gone. And this issue could be reproduced in 1200s. All detailed info: https://github.com/xupengfe/syzkaller_logs/tree/main/240823_212601_asm_sysvec_apic_timer_interrupt Syzkaller repro code: https://github.com/xupengfe/syzkaller_logs/blob/main/240823_212601_asm_sysvec_apic_timer_interrupt/repro.c Syzkaller repro syscall steps: https://github.com/xupengfe/syzkaller_logs/blob/main/240823_212601_asm_sysvec_apic_timer_interrupt/repro.prog Syzkaller report: https://github.com/xupengfe/syzkaller_logs/blob/main/240823_212601_asm_sysvec_apic_timer_interrupt/repro.report Kconfig(make olddefconfig): https://github.com/xupengfe/syzkaller_logs/blob/main/240823_212601_asm_sysvec_apic_timer_interrupt/kconfig_origin Bisect info: https://github.com/xupengfe/syzkaller_logs/blob/main/240823_212601_asm_sysvec_apic_timer_interrupt/bisect_info.log bzImage: https://github.com/xupengfe/syzkaller_logs/raw/main/240823_212601_asm_sysvec_apic_timer_interrupt/bzImage_47ac09b91befbb6a235ab620c32af719f8208399.tar.gz Issue dmesg: https://github.com/xupengfe/syzkaller_logs/blob/main/240823_212601_asm_sysvec_apic_timer_interrupt/47ac09b91befbb6a235ab620c32af719f8208399_dmesg.log " [ 22.518698] hrtimer: interrupt took 13103 ns [ 30.382700] clocksource: Long readout interval, skipping watchdog check: cs_nsec: 2079936720 wd_nsec: 2079936828 [ 378.038693] clocksource: Long readout interval, skipping watchdog check: cs_nsec: 7719948786 wd_nsec: 7719948793 [ 736.508865] watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [repro:193160] [ 736.509218] Modules linked in: [ 736.509369] irq event stamp: 15405229 [ 736.509539] hardirqs last enabled at (15405228): [<ffffffff8579c9de>] irqentry_exit+0x3e/0xa0 [ 736.509947] hardirqs last disabled at (15405229): [<ffffffff8579ae14>] sysvec_apic_timer_interrupt+0x14/0xc0 [ 736.510383] softirqs last enabled at (9218742): [<ffffffff81289fb9>] __irq_exit_rcu+0xa9/0x120 [ 736.510776] softirqs last disabled at (9218745): [<ffffffff81289fb9>] __irq_exit_rcu+0xa9/0x120 [ 736.511167] CPU: 0 UID: 0 PID: 193160 Comm: repro Not tainted 6.11.0-rc4-47ac09b91bef+ #1 [ 736.511529] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 [ 736.512039] RIP: 0010:__rcu_read_unlock+0x284/0x560 [ 736.512272] Code: 8f 00 00 00 84 d2 0f 84 87 00 00 00 bf 09 00 00 00 e8 d0 0b dc ff 4d 85 f6 0f 84 68 fe ff ff e8 f2 83 26 00 fb 0f 1f 44 00 00 <e9> 58 fe ff ff 0f 0b 48 83 c4 08 5b 41 5c 41 5d 41 5e 41 5f 5d c3 [ 736.513091] RSP: 0018:ffff88806c609938 EFLAGS: 00000212 [ 736.513330] RAX: 0000000000e956e0 RBX: ffff88806c649600 RCX: 1ffffffff14ae71b [ 736.513648] RDX: 0000000000000000 RSI: 0000000000000101 RDI: 0000000000000000 [ 736.513974] RBP: ffff88806c609968 R08: 0000000000000001 R09: fffffbfff14a92b5 [ 736.514289] R10: ffffffff8a5495af R11: 0000000000000001 R12: ffff88801379ca00 [ 736.514606] R13: ffff88801379ca00 R14: 0000000000000200 R15: ffffffff86e619c0 [ 736.514935] FS: 00007f095e148740(0000) GS:ffff88806c600000(0000) knlGS:0000000000000000 [ 736.515293] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 736.515555] CR2: 0000000020000000 CR3: 0000000021944006 CR4: 0000000000770ef0 [ 736.515888] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 736.516215] DR3: 0000000000000000 DR6: 00000000ffff07f0 DR7: 0000000000000400 [ 736.516539] PKRU: 55555554 [ 736.516672] Call Trace: [ 736.516798] <IRQ> [ 736.516907] ? show_regs+0xa8/0xc0 [ 736.517080] ? watchdog_timer_fn+0x52f/0x6b0 [ 736.517284] ? __pfx_watchdog_timer_fn+0x10/0x10 [ 736.517503] ? __hrtimer_run_queues+0x5d6/0xb10 [ 736.517733] ? __pfx___hrtimer_run_queues+0x10/0x10 [ 736.517975] ? hrtimer_interrupt+0x324/0x7a0 [ 736.518193] ? __sysvec_apic_timer_interrupt+0x10b/0x410 [ 736.518443] ? debug_smp_processor_id+0x20/0x30 [ 736.518663] ? sysvec_apic_timer_interrupt+0x4b/0xc0 [ 736.518901] ? asm_sysvec_apic_timer_interrupt+0x1f/0x30 [ 736.519162] ? __rcu_read_unlock+0x284/0x560 [ 736.519370] ? __rcu_read_unlock+0x27e/0x560 [ 736.519579] __is_insn_slot_addr+0x14c/0x2a0 [ 736.519791] kernel_text_address+0x64/0xe0 [ 736.519991] __kernel_text_address+0x16/0x50 [ 736.520199] unwind_get_return_address+0x8c/0x100 [ 736.520424] ? __pfx_stack_trace_consume_entry+0x10/0x10 [ 736.520671] arch_stack_walk+0xa7/0x170 [ 736.520878] stack_trace_save+0x97/0xd0 [ 736.521064] ? __pfx_stack_trace_save+0x10/0x10 [ 736.521276] ? __pfx_mark_lock.part.0+0x10/0x10 [ 736.521499] kasan_save_stack+0x2c/0x60 [ 736.521681] ? kasan_save_stack+0x2c/0x60 [ 736.521870] ? kasan_save_track+0x18/0x40 [ 736.522057] ? kasan_save_free_info+0x3f/0x60 [ 736.522267] ? __kasan_slab_free+0x115/0x1a0 [ 736.522467] ? kfree+0xfe/0x330 [ 736.522622] ? free_ctx+0x22/0x30 [ 736.522788] ? rcu_core+0x877/0x18f0 [ 736.522967] ? rcu_core_si+0x12/0x20 [ 736.523142] ? handle_softirqs+0x1c7/0x870 [ 736.523334] ? __irq_exit_rcu+0xa9/0x120 [ 736.523519] ? irq_exit_rcu+0x12/0x30 [ 736.523693] ? sysvec_apic_timer_interrupt+0xa5/0xc0 [ 736.523922] ? asm_sysvec_apic_timer_interrupt+0x1f/0x30 [ 736.524165] ? lock_acquire+0x1ff/0x580 [ 736.524352] ? _raw_spin_lock+0x38/0x50 [ 736.524534] ? do_fcntl+0xa95/0x1400 [ 736.524709] ? __x64_sys_fcntl+0x179/0x210 [ 736.524906] ? x64_sys_call+0x5b9/0x20d0 [ 736.525094] ? do_syscall_64+0x6d/0x140 [ 736.525276] ? entry_SYSCALL_64_after_hwframe+0x76/0x7e [ 736.525529] ? __pfx___lock_acquire+0x10/0x10 [ 736.525736] ? do_raw_spin_trylock+0xbf/0x190 [ 736.525949] ? free_unref_page_commit+0x3c0/0xfb0 [ 736.526176] ? __this_cpu_preempt_check+0x21/0x30 [ 736.526399] ? lock_acquire+0x1de/0x580 [ 736.526587] ? free_ctx+0x22/0x30 [ 736.526753] kasan_save_track+0x18/0x40 [ 736.526944] kasan_save_free_info+0x3f/0x60 [ 736.527146] __kasan_slab_free+0x115/0x1a0 [ 736.527341] ? free_ctx+0x22/0x30 [ 736.527503] kfree+0xfe/0x330 [ 736.527655] ? rcu_core+0x875/0x18f0 [ 736.527833] free_ctx+0x22/0x30 [ 736.527991] rcu_core+0x877/0x18f0 [ 736.528165] ? __pfx_rcu_core+0x10/0x10 [ 736.528365] rcu_core_si+0x12/0x20 [ 736.528535] handle_softirqs+0x1c7/0x870 [ 736.528734] __irq_exit_rcu+0xa9/0x120 [ 736.528915] irq_exit_rcu+0x12/0x30 [ 736.529085] sysvec_apic_timer_interrupt+0xa5/0xc0 [ 736.529309] </IRQ> [ 736.529414] <TASK> [ 736.529522] asm_sysvec_apic_timer_interrupt+0x1f/0x30 [ 736.529762] RIP: 0010:lock_acquire+0x1ff/0x580 [ 736.529974] Code: 48 83 c4 28 e8 72 73 37 04 b8 ff ff ff ff 65 0f c1 05 fd b6 c0 7e 83 f8 01 0f 85 d9 02 00 00 4d 85 ff 74 06 fb 0f 1f 44 00 00 <48> b8 00 00 00 00 00 fc ff df 48 01 c3 48 c7 03 00 00 00 00 48 c7 [ 736.530786] RSP: 0018:ffff88801aa0fcd0 EFLAGS: 00000206 [ 736.531031] RAX: 0000000000000001 RBX: 1ffff11003541f9e RCX: 1ffff11003541f82 [ 736.531348] RDX: 1ffff110026f3b07 RSI: 0000000000000001 RDI: 0000000000000000 [ 736.531668] RBP: ffff88801aa0fdb8 R08: 0000000000000000 R09: fffffbfff14a92b5 [ 736.531994] R10: ffffffff8a5495af R11: 0000000000000001 R12: 0000000000000001 [ 736.532318] R13: 0000000000000000 R14: ffff88800f65a028 R15: 0000000000000200 [ 736.532660] ? __pfx_lock_acquire+0x10/0x10 [ 736.532860] ? _raw_spin_unlock+0x31/0x60 [ 736.533063] ? up_write+0x1c0/0x550 [ 736.533234] ? fasync_helper+0x77/0xc0 [ 736.533420] _raw_spin_lock+0x38/0x50 [ 736.533595] ? do_fcntl+0xa95/0x1400 [ 736.533775] do_fcntl+0xa95/0x1400 [ 736.533948] ? __pfx_do_fcntl+0x10/0x10 [ 736.534137] ? trace_hardirqs_on+0x51/0x60 [ 736.534336] ? seqcount_lockdep_reader_access.constprop.0+0xc0/0xd0 [ 736.534619] ? __sanitizer_cov_trace_cmp4+0x1a/0x20 [ 736.534853] ? __sanitizer_cov_trace_const_cmp4+0x1a/0x20 [ 736.535104] ? security_file_fcntl+0x9d/0xd0 [ 736.535315] __x64_sys_fcntl+0x179/0x210 [ 736.535508] x64_sys_call+0x5b9/0x20d0 [ 736.535687] do_syscall_64+0x6d/0x140 [ 736.535866] entry_SYSCALL_64_after_hwframe+0x76/0x7e [ 736.536099] RIP: 0033:0x7f095de3ee5d [ 736.536273] Code: ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 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 8b 0d 93 af 1b 00 f7 d8 64 89 01 48 [ 736.537075] RSP: 002b:00007ffea8175048 EFLAGS: 00000217 ORIG_RAX: 0000000000000048 [ 736.537411] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f095de3ee5d [ 736.537736] RDX: 0000000000002400 RSI: 0000000000000004 RDI: 0000000000000003 [ 736.538053] RBP: 00007ffea8175060 R08: 00007ffea8175060 R09: 00007ffea8175060 [ 736.538371] R10: 00007ffea8175060 R11: 0000000000000217 R12: 00007ffea81751d8 [ 736.538689] R13: 000000000040547a R14: 0000000000407df8 R15: 00007f095e193000 [ 736.539023] </TASK> [ 736.539132] Kernel panic - not syncing: softlockup: hung tasks " Hope it's helpful. Thanks! --- If you don't need the following environment to reproduce the problem or if you already have one reproduced environment, please ignore the following information. How to reproduce: git clone https://gitlab.com/xupengfe/repro_vm_env.git cd repro_vm_env tar -xvf repro_vm_env.tar.gz cd repro_vm_env; ./start3.sh // it needs qemu-system-x86_64 and I used v7.1.0 // start3.sh will load bzImage_2241ab53cbb5cdb08a6b2d4688feb13971058f65 v6.2-rc5 kernel // You could change the bzImage_xxx as you want // Maybe you need to remove line "-drive if=pflash,format=raw,readonly=on,file=./OVMF_CODE.fd \" for different qemu version You could use below command to log in, there is no password for root. ssh -p 10023 root@localhost After login vm(virtual machine) successfully, you could transfer reproduced binary to the vm by below way, and reproduce the problem in vm: gcc -pthread -o repro repro.c scp -P 10023 repro root@localhost:/root/ Get the bzImage for target kernel: Please use target kconfig and copy it to kernel_src/.config make olddefconfig make -jx bzImage //x should equal or less than cpu num your pc has Fill the bzImage file into above start3.sh to load the target kernel in vm. Tips: If you already have qemu-system-x86_64, please ignore below info. If you want to install qemu v7.1.0 version: git clone https://github.com/qemu/qemu.git cd qemu git checkout -f v7.1.0 mkdir build cd build yum install -y ninja-build.x86_64 yum -y install libslirp-devel.x86_64 ../configure --target-list=x86_64-softmmu --enable-kvm --enable-vnc --enable-gtk --enable-sdl --enable-usb-redir --enable-slirp make make install Best Regards, Thanks! On 2023-04-17 at 10:46:22 -0000, tip-bot2 for Yang Jihong wrote: > The following commit has been merged into the perf/core branch of tip: > > Commit-ID: 15def34e2635ab7e0e96f1bc32e1b69609f14942 > Gitweb: https://git.kernel.org/tip/15def34e2635ab7e0e96f1bc32e1b69609f14942 > Author: Yang Jihong <yangjihong1@xxxxxxxxxx> > AuthorDate: Mon, 27 Feb 2023 10:35:08 +08:00 > Committer: Peter Zijlstra <peterz@xxxxxxxxxxxxx> > CommitterDate: Fri, 14 Apr 2023 16:08:22 +02:00 > > perf/core: Fix hardlockup failure caused by perf throttle > > commit e050e3f0a71bf ("perf: Fix broken interrupt rate throttling") > introduces a change in throttling threshold judgment. Before this, > compare hwc->interrupts and max_samples_per_tick, then increase > hwc->interrupts by 1, but this commit reverses order of these two > behaviors, causing the semantics of max_samples_per_tick to change. > In literal sense of "max_samples_per_tick", if hwc->interrupts == > max_samples_per_tick, it should not be throttled, therefore, the judgment > condition should be changed to "hwc->interrupts > max_samples_per_tick". > > In fact, this may cause the hardlockup to fail, The minimum value of > max_samples_per_tick may be 1, in this case, the return value of > __perf_event_account_interrupt function is 1. > As a result, nmi_watchdog gets throttled, which would stop PMU (Use x86 > architecture as an example, see x86_pmu_handle_irq). > > Fixes: e050e3f0a71b ("perf: Fix broken interrupt rate throttling") > Signed-off-by: Yang Jihong <yangjihong1@xxxxxxxxxx> > Signed-off-by: Peter Zijlstra (Intel) <peterz@xxxxxxxxxxxxx> > Link: https://lkml.kernel.org/r/20230227023508.102230-1-yangjihong1@xxxxxxxxxx > --- > kernel/events/core.c | 4 ++-- > 1 file changed, 2 insertions(+), 2 deletions(-) > > diff --git a/kernel/events/core.c b/kernel/events/core.c > index fb3e436..82b95b8 100644 > --- a/kernel/events/core.c > +++ b/kernel/events/core.c > @@ -9433,8 +9433,8 @@ __perf_event_account_interrupt(struct perf_event *event, int throttle) > hwc->interrupts = 1; > } else { > hwc->interrupts++; > - if (unlikely(throttle > - && hwc->interrupts >= max_samples_per_tick)) { > + if (unlikely(throttle && > + hwc->interrupts > max_samples_per_tick)) { > __this_cpu_inc(perf_throttled_count); > tick_dep_set_cpu(smp_processor_id(), TICK_DEP_BIT_PERF_EVENTS); > hwc->interrupts = MAX_INTERRUPTS;
