Re: [PATCH V4 2/2] perf/x86/intel/ds: Delay the threshold update

[Yujie Liu]

Hi Peter,

On Tue, Apr 25, 2023 at 01:19:55PM +0200, Peter Zijlstra wrote:
> On Tue, Apr 25, 2023 at 03:16:29PM +0800, kernel test robot wrote:
> > Hello,
> > 
> > kernel test robot noticed "Kernel_panic-not_syncing:Timeout:Not_all_CPUs_entered_broadcast_exception_handler" on:
> > 
> > commit: a17c97370d1fb9b2eac75c85136a1f70ec44eded ("[PATCH V4 2/2] perf/x86/intel/ds: Delay the threshold update")
> > url: https://github.com/intel-lab-lkp/linux/commits/kan-liang-linux-intel-com/perf-x86-intel-ds-Delay-the-threshold-update/20230422-024743
> > base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git 15def34e2635ab7e0e96f1bc32e1b69609f14942
> > patch link: https://lore.kernel.org/all/20230421184529.3320912-2-kan.liang@xxxxxxxxxxxxxxx/
> > patch subject: [PATCH V4 2/2] perf/x86/intel/ds: Delay the threshold update
> > 
> 
> > [  224.064675][   C84] mce: CPUs not responding to MCE broadcast (may include false positives): 0-83,85-223
> > [  224.064681][   C84] Kernel panic - not syncing: Timeout: Not all CPUs entered broadcast exception handler
> > [  225.089881][   C84] Shutting down cpus with NMI
> > [  225.129381][   C84] Kernel Offset: disabled
> 
> That seems very unrelated to the patch at hand; was this bisect double
> checked?

We rechecked this case and the bisect should be valid.

We also ran this test on different platforms. The issue can be
reproduced on Sapphire Rapids and Ice Lake. The same thing is they
have a similar "split lock detection" warning when the test started,
but with different dmesg after that. The issue cannot be reproduced
on Cascade Lake.

Another thing to note is that the patchset was applied on commit
15def34e2635 of tip tree (the head of perf/core branch then). Not sure
if this is the correct base to test it.

Please check the details as below:

== Sapphire Rapids ==

# tail of dmesg

[  217.823350][T24250] x86/split lock detection: #AC: qemu-system-x86/24250 took a split_lock trap at address: 0x1e3
[  222.633517][  C218] mce: CPUs not responding to MCE broadcast (may include false positives): 0-217,219-223
[  222.633523][  C218] Kernel panic - not syncing: Timeout: Not all CPUs entered broadcast exception handler
[  223.663277][  C218] Shutting down cpus with NMI
[  223.704639][  C218] Kernel Offset: disabled
[  232.753628][  C218] pstore: backend (erst) writing error (-28)

# result comparison

tbox_group/testcase/rootfs/kconfig/compiler:
  lkp-spr-2sp1/kvm-unit-tests-qemu/debian-11.1-x86_64-20220510.cgz/x86_64-rhel-8.3-kvm/gcc-11

commit: 
  1283dc16325e3 ("perf/x86/intel/ds: Flush the PEBS buffer in PEBS enable")
  a17c97370d1fb ("perf/x86/intel/ds: Delay the threshold update")

1283dc16325e3b9d a17c97370d1fb9b2eac75c85136 
---------------- --------------------------- 
       fail:runs  %reproduction    fail:runs
           |             |             |    
           :6           83%           5:6     dmesg.Kernel_panic-not_syncing:Timeout:Not_all_CPUs_entered_broadcast_exception_handler


== Ice Lake ==

# tail of dmesg

[  234.463750][T23542] x86/split lock detection: #AC: qemu-system-x86/23542 took a split_lock trap at address: 0x1e3
[  261.554115][   C48] watchdog: BUG: soft lockup - CPU#48 stuck for 26s! [kworker/48:1:933]
[  261.563287][   C48] Modules linked in: kvm_intel kvm irqbypass btrfs blake2b_generic xor raid6_pq zstd_compress libcrc32c sd_mod t10_pi crc64_rocksoft_generic crc64_rocksoft crc64 sg intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel ipmi_ssif sha512_ssse3 rapl ast ahci drm_shmem_helper libahci drm_kms_helper intel_cstate acpi_ipmi mei_me ipmi_si syscopyarea ioatdma sysfillrect ipmi_devintf libata sysimgblt mei intel_uncore wmi dca joydev ipmi_msghandler acpi_pad acpi_power_meter drm fuse ip_tables [last unloaded: irqbypass]
[  261.622458][   C48] CPU: 48 PID: 933 Comm: kworker/48:1 Not tainted 6.3.0-rc3-00006-ga17c97370d1f #1
[  261.632557][   C48] Workqueue: events jump_label_update_timeout
[ 261.639444][ C48] RIP: 0010:smp_call_function_many_cond (kernel/smp.c:442 kernel/smp.c:987)
[ 261.646846][ C48] Code: 38 c8 7c 08 84 c9 0f 85 16 05 00 00 8b 45 08 a8 01 74 2e 48 89 f1 49 89 f7 48 c1 e9 03 41 83 e7 07 4c 01 f1 41 83 c7 03 f3 90 <0f> b6 01 41 38 c7 7c 08 84 c0 0f 85 20 04 00 00 8b 45 08 a8 01 75
All code
========
   0:   38 c8                   cmp    %cl,%al
   2:   7c 08                   jl     0xc
   4:   84 c9                   test   %cl,%cl
   6:   0f 85 16 05 00 00       jne    0x522
   c:   8b 45 08                mov    0x8(%rbp),%eax
   f:   a8 01                   test   $0x1,%al
  11:   74 2e                   je     0x41
  13:   48 89 f1                mov    %rsi,%rcx
  16:   49 89 f7                mov    %rsi,%r15
  19:   48 c1 e9 03             shr    $0x3,%rcx
  1d:   41 83 e7 07             and    $0x7,%r15d
  21:   4c 01 f1                add    %r14,%rcx
  24:   41 83 c7 03             add    $0x3,%r15d
  28:   f3 90                   pause
  2a:*  0f b6 01                movzbl (%rcx),%eax              <-- trapping instruction
  2d:   41 38 c7                cmp    %al,%r15b
  30:   7c 08                   jl     0x3a
  32:   84 c0                   test   %al,%al
  34:   0f 85 20 04 00 00       jne    0x45a
  3a:   8b 45 08                mov    0x8(%rbp),%eax
  3d:   a8 01                   test   $0x1,%al
  3f:   75                      .byte 0x75

Code starting with the faulting instruction
===========================================
   0:   0f b6 01                movzbl (%rcx),%eax
   3:   41 38 c7                cmp    %al,%r15b
   6:   7c 08                   jl     0x10
   8:   84 c0                   test   %al,%al
   a:   0f 85 20 04 00 00       jne    0x430
  10:   8b 45 08                mov    0x8(%rbp),%eax
  13:   a8 01                   test   $0x1,%al
  15:   75                      .byte 0x75
[  261.668227][   C48] RSP: 0018:ffa000000af07be8 EFLAGS: 00000202
[  261.675122][   C48] RAX: 0000000000000011 RBX: ff1100202043aa40 RCX: ffe21c04041980ed
[  261.683923][   C48] RDX: 0000000000000061 RSI: ff11002020cc0768 RDI: ffffffff841ecbc8
[  261.692703][   C48] RBP: ff11002020cc0760 R08: 0000000000000000 R09: ff11001083a9b867
[  261.701490][   C48] R10: ffe21c021075370c R11: 0000000000000001 R12: ffe21c0404087549
[  261.710264][   C48] R13: ffe21c0404087548 R14: dffffc0000000000 R15: 0000000000000003
[  261.719023][   C48] FS:  0000000000000000(0000) GS:ff11002020400000(0000) knlGS:0000000000000000
[  261.728751][   C48] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  261.736129][   C48] CR2: 00007f41400060a8 CR3: 000000207e246002 CR4: 0000000000773ee0
[  261.744887][   C48] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  261.753644][   C48] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  261.762385][   C48] PKRU: 55555554
[  261.766683][   C48] Call Trace:
[  261.770714][   C48]  <TASK>
[ 261.774389][ C48] ? optimize_nops (arch/x86/kernel/alternative.c:1764)
[ 261.779882][ C48] on_each_cpu_cond_mask (arch/x86/include/asm/preempt.h:85 kernel/smp.c:1156)
[ 261.785707][ C48] text_poke_bp_batch (include/linux/smp.h:71 arch/x86/kernel/alternative.c:1770 arch/x86/kernel/alternative.c:1970)
[ 261.791446][ C48] ? do_sync_core (arch/x86/kernel/alternative.c:1940)
WARNING! Modules path isn't set, but is needed to parse this symbol
[ 261.796644][ C48] ? kvm_irq_delivery_to_apic+0x31c/0x890 kvm
[ 261.803629][ C48] ? __cond_resched (kernel/sched/core.c:8486)
[ 261.808993][ C48] ? mutex_lock (arch/x86/include/asm/atomic64_64.h:190 include/linux/atomic/atomic-long.h:443 include/linux/atomic/atomic-instrumented.h:1781 kernel/locking/mutex.c:171 kernel/locking/mutex.c:285)
[ 261.813986][ C48] ? __mutex_lock_slowpath (kernel/locking/mutex.c:282)
[ 261.819917][ C48] ? kernel_text_address (kernel/extable.c:119 kernel/extable.c:94)
[ 261.825681][ C48] text_poke_finish (arch/x86/kernel/alternative.c:2162 arch/x86/kernel/alternative.c:2158 arch/x86/kernel/alternative.c:2168)
[ 261.830991][ C48] arch_jump_label_transform_apply (arch/x86/kernel/jump_label.c:147)
[ 261.837598][ C48] __static_key_slow_dec_cpuslocked+0x3d/0x50
[ 261.844899][ C48] jump_label_update_timeout (kernel/jump_label.c:292)
[ 261.850966][ C48] process_one_work (kernel/workqueue.c:2395)
[ 261.856506][ C48] worker_thread (include/linux/list.h:292 kernel/workqueue.c:2538)
[ 261.861697][ C48] ? __kthread_parkme (arch/x86/include/asm/bitops.h:207 (discriminator 4) arch/x86/include/asm/bitops.h:239 (discriminator 4) include/asm-generic/bitops/instrumented-non-atomic.h:142 (discriminator 4) kernel/kthread.c:270 (discriminator 4))
[ 261.867219][ C48] ? schedule (arch/x86/include/asm/preempt.h:85 (discriminator 1) kernel/sched/core.c:6699 (discriminator 1))
[ 261.872116][ C48] ? process_one_work (kernel/workqueue.c:2480)
[ 261.877879][ C48] ? process_one_work (kernel/workqueue.c:2480)
[ 261.883622][ C48] kthread (kernel/kthread.c:376)
[ 261.888220][ C48] ? kthread_complete_and_exit (kernel/kthread.c:331)
[ 261.894381][ C48] ret_from_fork (arch/x86/entry/entry_64.S:314)
[  261.899315][   C48]  </TASK>
[  261.902834][   C48] Kernel panic - not syncing: softlockup: hung tasks
[  261.909991][   C48] CPU: 48 PID: 933 Comm: kworker/48:1 Tainted: G             L     6.3.0-rc3-00006-ga17c97370d1f #1
[  261.921226][   C48] Workqueue: events jump_label_update_timeout
[  261.927764][   C48] Call Trace:
[  261.931505][   C48]  <IRQ>
[ 261.934778][ C48] dump_stack_lvl (lib/dump_stack.c:107 (discriminator 1))
[ 261.939688][ C48] panic (kernel/panic.c:340)
[ 261.943981][ C48] ? panic_smp_self_stop+0x70/0x70
[ 261.949482][ C48] ? add_taint (arch/x86/include/asm/bitops.h:60 include/asm-generic/bitops/instrumented-atomic.h:29 kernel/panic.c:539)
[ 261.954103][ C48] watchdog_timer_fn (kernel/watchdog.c:435)
[ 261.959397][ C48] ? lockup_detector_update_enable (kernel/watchdog.c:355)
[ 261.965721][ C48] __hrtimer_run_queues (kernel/time/hrtimer.c:1685 kernel/time/hrtimer.c:1749)
[ 261.971263][ C48] ? sched_clock_cpu (kernel/sched/clock.c:384)
[ 261.976454][ C48] ? enqueue_hrtimer (kernel/time/hrtimer.c:1719)
[ 261.981725][ C48] ? _raw_read_unlock_irqrestore (kernel/locking/spinlock.c:161)
[ 261.987864][ C48] ? ktime_get_update_offsets_now (kernel/time/timekeeping.c:292 (discriminator 3) kernel/time/timekeeping.c:388 (discriminator 3) kernel/time/timekeeping.c:2320 (discriminator 3))
[ 261.994181][ C48] hrtimer_interrupt (kernel/time/hrtimer.c:1814)
[ 261.999450][ C48] __sysvec_apic_timer_interrupt (arch/x86/include/asm/jump_label.h:27 include/linux/jump_label.h:207 arch/x86/include/asm/trace/irq_vectors.h:41 arch/x86/kernel/apic/apic.c:1114)
[ 262.005670][ C48] sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1107 (discriminator 14))
[  262.011616][   C48]  </IRQ>
[  262.014869][   C48]  <TASK>
[ 262.018126][ C48] asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:645)
[ 262.024418][ C48] RIP: 0010:smp_call_function_many_cond (kernel/smp.c:442 kernel/smp.c:987)
[ 262.031329][ C48] Code: 38 c8 7c 08 84 c9 0f 85 16 05 00 00 8b 45 08 a8 01 74 2e 48 89 f1 49 89 f7 48 c1 e9 03 41 83 e7 07 4c 01 f1 41 83 c7 03 f3 90 <0f> b6 01 41 38 c7 7c 08 84 c0 0f 85 20 04 00 00 8b 45 08 a8 01 75
All code
========
   0:   38 c8                   cmp    %cl,%al
   2:   7c 08                   jl     0xc
   4:   84 c9                   test   %cl,%cl
   6:   0f 85 16 05 00 00       jne    0x522
   c:   8b 45 08                mov    0x8(%rbp),%eax
   f:   a8 01                   test   $0x1,%al
  11:   74 2e                   je     0x41
  13:   48 89 f1                mov    %rsi,%rcx
  16:   49 89 f7                mov    %rsi,%r15
  19:   48 c1 e9 03             shr    $0x3,%rcx
  1d:   41 83 e7 07             and    $0x7,%r15d
  21:   4c 01 f1                add    %r14,%rcx
  24:   41 83 c7 03             add    $0x3,%r15d
  28:   f3 90                   pause
  2a:*  0f b6 01                movzbl (%rcx),%eax              <-- trapping instruction
  2d:   41 38 c7                cmp    %al,%r15b
  30:   7c 08                   jl     0x3a
  32:   84 c0                   test   %al,%al
  34:   0f 85 20 04 00 00       jne    0x45a
  3a:   8b 45 08                mov    0x8(%rbp),%eax
  3d:   a8 01                   test   $0x1,%al
  3f:   75                      .byte 0x75

Code starting with the faulting instruction
===========================================
   0:   0f b6 01                movzbl (%rcx),%eax
   3:   41 38 c7                cmp    %al,%r15b
   6:   7c 08                   jl     0x10
   8:   84 c0                   test   %al,%al
   a:   0f 85 20 04 00 00       jne    0x430
  10:   8b 45 08                mov    0x8(%rbp),%eax
  13:   a8 01                   test   $0x1,%al
  15:   75                      .byte 0x75
[  262.051777][   C48] RSP: 0018:ffa000000af07be8 EFLAGS: 00000202
[  262.058210][   C48] RAX: 0000000000000011 RBX: ff1100202043aa40 RCX: ffe21c04041980ed
[  262.066559][   C48] RDX: 0000000000000061 RSI: ff11002020cc0768 RDI: ffffffff841ecbc8
[  262.074915][   C48] RBP: ff11002020cc0760 R08: 0000000000000000 R09: ff11001083a9b867
[  262.083270][   C48] R10: ffe21c021075370c R11: 0000000000000001 R12: ffe21c0404087549
[  262.091623][   C48] R13: ffe21c0404087548 R14: dffffc0000000000 R15: 0000000000000003
[ 262.099983][ C48] ? smp_call_function_many_cond (kernel/smp.c:983 (discriminator 1))
[ 262.106355][ C48] ? optimize_nops (arch/x86/kernel/alternative.c:1764)
[ 262.111513][ C48] on_each_cpu_cond_mask (arch/x86/include/asm/preempt.h:85 kernel/smp.c:1156)
[ 262.117014][ C48] text_poke_bp_batch (include/linux/smp.h:71 arch/x86/kernel/alternative.c:1770 arch/x86/kernel/alternative.c:1970)
[ 262.122431][ C48] ? do_sync_core (arch/x86/kernel/alternative.c:1940)
WARNING! Modules path isn't set, but is needed to parse this symbol
[ 262.127320][ C48] ? kvm_irq_delivery_to_apic+0x31c/0x890 kvm
[ 262.133997][ C48] ? __cond_resched (kernel/sched/core.c:8486)
[ 262.139055][ C48] ? mutex_lock (arch/x86/include/asm/atomic64_64.h:190 include/linux/atomic/atomic-long.h:443 include/linux/atomic/atomic-instrumented.h:1781 kernel/locking/mutex.c:171 kernel/locking/mutex.c:285)
[ 262.143768][ C48] ? __mutex_lock_slowpath (kernel/locking/mutex.c:282)
[ 262.149438][ C48] ? kernel_text_address (kernel/extable.c:119 kernel/extable.c:94)
[ 262.154935][ C48] text_poke_finish (arch/x86/kernel/alternative.c:2162 arch/x86/kernel/alternative.c:2158 arch/x86/kernel/alternative.c:2168)
[ 262.159994][ C48] arch_jump_label_transform_apply (arch/x86/kernel/jump_label.c:147)
[ 262.166369][ C48] __static_key_slow_dec_cpuslocked+0x3d/0x50
[ 262.173444][ C48] jump_label_update_timeout (kernel/jump_label.c:292)
[ 262.179304][ C48] process_one_work (kernel/workqueue.c:2395)
[ 262.184641][ C48] worker_thread (include/linux/list.h:292 kernel/workqueue.c:2538)
[ 262.189631][ C48] ? __kthread_parkme (arch/x86/include/asm/bitops.h:207 (discriminator 4) arch/x86/include/asm/bitops.h:239 (discriminator 4) include/asm-generic/bitops/instrumented-non-atomic.h:142 (discriminator 4) kernel/kthread.c:270 (discriminator 4))
[ 262.194965][ C48] ? schedule (arch/x86/include/asm/preempt.h:85 (discriminator 1) kernel/sched/core.c:6699 (discriminator 1))
[ 262.199676][ C48] ? process_one_work (kernel/workqueue.c:2480)
[ 262.205247][ C48] ? process_one_work (kernel/workqueue.c:2480)
[ 262.210810][ C48] kthread (kernel/kthread.c:376)
[ 262.215250][ C48] ? kthread_complete_and_exit (kernel/kthread.c:331)
[ 262.221254][ C48] ret_from_fork (arch/x86/entry/entry_64.S:314)
[  262.226045][   C48]  </TASK>

# result comparison

compiler/kconfig/rootfs/tbox_group/testcase:
  gcc-11/x86_64-rhel-8.3-kvm/debian-11.1-x86_64-20220510.cgz/lkp-icl-2sp6/kvm-unit-tests-qemu

commit: 
  1283dc16325e3 ("perf/x86/intel/ds: Flush the PEBS buffer in PEBS enable")
  a17c97370d1fb ("perf/x86/intel/ds: Delay the threshold update")

1283dc16325e3b9d a17c97370d1fb9b2eac75c85136 
---------------- --------------------------- 
       fail:runs  %reproduction    fail:runs
           |             |             |    
           :6          100%           6:6     dmesg.BUG:soft_lockup-CPU##stuck_for#s![kworker:#:#]
           :6           83%           5:6     dmesg.Kernel_panic-not_syncing:softlockup:hung_tasks
           :6          100%           6:6     dmesg.RIP:smp_call_function_many_cond


--
Best Regards,
Yujie