Re: [PATCH 0/4] perf: Make SIGTRAP and __perf_pending_irq() work on RT.

[Arnaldo Carvalho de Melo <acme@kernel.org>]

On Mon, Mar 11, 2024 at 05:31:09PM +0100, Marco Elver wrote:
> On Mon, 11 Mar 2024 at 16:59, Sebastian Andrzej Siewior
> <bigeasy@linutronix.de> wrote:
> >
> > On 2024-03-11 11:34:18 [+0100], Marco Elver wrote:
> > > Unfortunately there's a bug in it somewhere. It can be reproduced with
> > > tools/testing/selftests/perf_events/remove_on_exec.
> > >
> > > (FWIW, the kselftests in that directory are more aggressive test cases
> > > that I never figured out how to properly port to the 'perf test'
> > > framework: sigtrap_threads is a more aggressive version of the 'sigtrap'
> > > perf test, and remove_on_exec has no perf test counterpart.)
> >
> > You posted to warnings, I can only reproduce the second one. Based on the
> > backtrace it is obvious what happens and I dare to say that I know why…
> > Let me try address them.
> 
> I guess I got lucky with hitting 2 warnings instantly. It might be
> necessary to run remove_on_exec several times, or even start several
> instances of it concurrently (something like "for x in {0..100}; do
> (./remove_on_exec &); done" might do the trick).

Doing this parallel remove_on_exec selftest, without Sebastian's patchs I
eventually hit, which is the original, the following output, then I
managed to replicate Marco's two different splats, see below.

[  275.644373] BUG: scheduling while atomic: remove_on_exec/10716/0x00000002
[  275.644378] Modules linked in: xfs libcrc32c i915 i2c_algo_bit drm_buddy ttm intel_gtt drm_display_helper drm_kms_helper sr_mod sd_mod cdrom t10_pi sg drm sdhci_pci cqhci ahci crct10dif_pclmul crc32_pclmul libahci crc32c_intel sdhci e1000e libata ghash_clmulni_intel mmc_core cec video wmi serio_raw dm_mirror dm_region_hash dm_log dm_mod fuse
[  275.644402] Preemption disabled at:
[  275.644402] [<0000000000000000>] 0x0
[  275.644407] CPU: 0 PID: 10716 Comm: remove_on_exec Kdump: loaded Tainted: G        W          6.8.0-rc7-rt6 #1
[  275.644410] Hardware name: LENOVO 427623U/427623U, BIOS 8BET45WW (1.25 ) 05/18/2011
[  275.644411] Call Trace:
[  275.644414]  <TASK>
[  275.644416]  dump_stack_lvl+0x51/0x70
[  275.644421]  __schedule_bug+0x89/0xa0
[  275.644426]  schedule_debug.constprop.0+0xd1/0x120
[  275.644430]  __schedule+0x50/0x680
[  275.644433]  ? _raw_spin_lock+0x13/0x40
[  275.644436]  ? __sigqueue_alloc+0x81/0x120
[  275.644440]  schedule_rtlock+0x1e/0x40
[  275.644443]  rtlock_slowlock_locked+0xcd/0x270
[  275.644446]  rt_spin_lock+0x41/0x60
[  275.644448]  obj_cgroup_charge+0x3c/0x1d0
[  275.644451]  kmem_cache_alloc+0x255/0x2a0
[  275.644455]  __sigqueue_alloc+0x81/0x120
[  275.644459]  __send_signal_locked+0x25c/0x3c0
[  275.644461]  ? send_signal_locked+0x3f/0x130
[  275.644464]  do_send_sig_info+0x54/0xb0
[  275.644467]  send_sig_perf+0x70/0x90
[  275.644470]  perf_pending_task+0x89/0xa0
[  275.644473]  task_work_run+0x59/0x90
[  275.644476]  irqentry_exit_to_user_mode+0x1dd/0x1e0
[  275.644480]  asm_sysvec_irq_work+0x16/0x20
[  275.644483] RIP: 0033:0x403376
[  275.644485] Code: 48 89 bd c8 fe ff ff 48 89 b5 c0 fe ff ff 48 89 95 b8 fe ff ff e8 1a df ff ff 89 85 24 ff ff ff 83 bd 24 ff ff ff 00 75 15 90 <8b> 05 84 53 00 00 85 c0 74 f6 bf 2a 00 00 00 e8 e6 dc ff ff 48 8d
[  275.644487] RSP: 002b:00007fffc462fde0 EFLAGS: 00000246
[  275.644489] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f442bd9a018
[  275.644490] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000001
[  275.644491] RBP: 00007fffc462ff30 R08: 0000000000000000 R09: 0000000000000000
[  275.644493] R10: 00007f442bd9a008 R11: 0000000000000246 R12: 00007fffc46301f8
[  275.644494] R13: 00000000004046cf R14: 0000000000407e08 R15: 00007f442bd99000
[  275.644497]  </TASK>
[  275.681832] BUG: using smp_processor_id() in preemptible [00000000] code: remove_on_exec/10716
[  275.681838] caller is perf_pending_task+0x34/0xa0



Now with Sebastian's patch series:

  612.723013] ------------[ cut here ]------------
[  612.723016] WARNING: CPU: 3 PID: 8655 at kernel/events/core.c:9595 __perf_event_overflow+0x21a/0x230
[  612.723026] Modules linked in: nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set nf_tables nfnetlink bnep sunrpc iwldvm intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp mac80211 snd_hda_codec_hdmi snd_ctl_led snd_hda_codec_conexant coretemp snd_hda_codec_generic kvm_intel snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi libarc4 snd_hda_codec kvm snd_hda_core iwlwifi snd_hwdep uvcvideo snd_seq uvc btusb snd_seq_device videobuf2_vmalloc btrtl snd_pcm videobuf2_memops btintel btbcm videobuf2_v4l2 btmtk videodev mei_wdt irqbypass thinkpad_acpi snd_timer rapl think_lmi iTCO_wdt cfg80211 bluetooth iTCO_vendor_support intel_cstate snd videobuf2_common i2c_i801 firmware_attributes_class mei_me mc pcspkr intel_uncore wmi_bmof ledtrig_audio i2c_smbus mei soundcore lpc_ich platform_profile rfkill joydev xfs libcrc32c i915 i2c_algo_bit drm_buddy ttm intel_gtt drm_display_helper
[  612.723090]  drm_kms_helper sr_mod sd_mod cdrom t10_pi sg drm crct10dif_pclmul ahci crc32_pclmul sdhci_pci libahci crc32c_intel e1000e cqhci libata sdhci ghash_clmulni_intel mmc_core cec video wmi serio_raw dm_mirror dm_region_hash dm_log dm_mod fuse
[  612.723111] CPU: 3 PID: 8655 Comm: remove_on_exec Kdump: loaded Not tainted 6.8.0-rc7.sebastian-rt6+ #1
[  612.723114] Hardware name: LENOVO 427623U/427623U, BIOS 8BET45WW (1.25 ) 05/18/2011
[  612.723115] RIP: 0010:__perf_event_overflow+0x21a/0x230
[  612.723120] Code: 45 31 ed 5b 5d 44 89 e8 41 5c 41 5d 41 5e c3 cc cc cc cc 48 c7 83 40 03 00 00 00 00 00 00 e9 03 ff ff ff 0f 0b e9 c8 fe ff ff <0f> 0b e9 77 ff ff ff 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00
[  612.723123] RSP: 0000:ffffb81e833abc50 EFLAGS: 00010087
[  612.723125] RAX: 00000000004045c1 RBX: ffff93e80107ec48 RCX: 00000000004045bb
[  612.723127] RDX: 0000000000000020 RSI: ffffffffac25de92 RDI: ffffffffac1f45ee
[  612.723128] RBP: ffffb81e833abcc0 R08: 0000000000000002 R09: ffffb81e833abcc0
[  612.723130] R10: 0000000000000000 R11: 0000000000000000 R12: ffffb81e833abf58
[  612.723131] R13: 0000000000000000 R14: 0000000000000001 R15: 0000000000000020
[  612.723132] FS:  00007f6a22d87600(0000) GS:ffff93eb1e2c0000(0000) knlGS:0000000000000000
[  612.723135] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  612.723136] CR2: 0000000000405730 CR3: 000000011687c003 CR4: 00000000000606f0
[  612.723138] Call Trace:
[  612.723139]  <TASK>
[  612.723141]  ? __warn+0x85/0x140
[  612.723145]  ? __perf_event_overflow+0x21a/0x230
[  612.723149]  ? report_bug+0x1c3/0x1d0
[  612.723155]  ? handle_bug+0x3c/0x70
[  612.723159]  ? exc_invalid_op+0x14/0x70
[  612.723163]  ? asm_exc_invalid_op+0x16/0x20
[  612.723170]  ? __perf_event_overflow+0x21a/0x230
[  612.723174]  handle_pmi_common+0x18b/0x400
[  612.723178]  ? kick_process+0x46/0xc0
[  612.723183]  ? migrate_enable+0xaa/0xf0
[  612.723188]  ? rt_spin_unlock+0x13/0x40
[  612.723191]  ? do_send_sig_info+0x63/0xb0
[  612.723195]  ? kill_pid_info+0x9f/0xb0
[  612.723199]  ? kill_something_info+0x170/0x1a0
[  612.723202]  ? rt_read_unlock+0x31/0x1a0
[  612.723205]  ? __x64_sys_kill+0x7f/0xb0
[  612.723209]  intel_pmu_handle_irq+0x112/0x2a0
[  612.723213]  perf_event_nmi_handler+0x28/0x50
[  612.723217]  nmi_handle+0x5e/0x150
[  612.723222]  default_do_nmi+0x6b/0x180
[  612.723225]  exc_nmi+0x10f/0x190
[  612.723227]  asm_exc_nmi+0xb1/0xfa
[  612.723230] RIP: 0033:0x4045c1
[  612.723233] Code: 8b 40 2c 85 c0 75 d4 83 45 c4 01 8b 45 c4 83 f8 1d 0f 86 3e fe ff ff 8b 05 4c 41 00 00 89 85 2c ff ff ff 90 8b 15 3f 41 00 00 <8b> 85 2c ff ff ff 39 c2 74 f0 90 90 c9 c3 55 48 89 e5 48 81 ec b0
[  612.723234] RSP: 002b:00007ffc40fd6c40 EFLAGS: 00000246
[  612.723236] RAX: 0000000000000005 RBX: 0000000000000000 RCX: 00007f6a22ba676b
[  612.723238] RDX: 0000000000000005 RSI: 0000000000000009 RDI: 00000000000021ed
[  612.723239] RBP: 00007ffc40fd6d40 R08: 00000000000021ed R09: 0000000000000000
[  612.723241] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffc40fd7008
[  612.723242] R13: 00000000004046cf R14: 0000000000407e08 R15: 00007f6a22dca000
[  612.723246]  </TASK>
[  612.723247] ---[ end trace 0000000000000000 ]---
[  617.892290] perf: interrupt took too long (2509 > 2500), lowering kernel.perf_event_max_sample_rate to 79000
[  618.992995] ------------[ cut here ]------------
[  618.992999] unexpected event refcount: 2; ptr=0000000022c05d43
[  618.993007] WARNING: CPU: 2 PID: 8967 at kernel/events/core.c:5240 free_event+0x36/0x40
[  618.993015] Modules linked in: nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set nf_tables nfnetlink bnep sunrpc iwldvm intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp mac80211 snd_hda_codec_hdmi snd_ctl_led snd_hda_codec_conexant coretemp snd_hda_codec_generic kvm_intel snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi libarc4 snd_hda_codec kvm snd_hda_core iwlwifi snd_hwdep uvcvideo snd_seq uvc btusb snd_seq_device videobuf2_vmalloc btrtl snd_pcm videobuf2_memops btintel btbcm videobuf2_v4l2 btmtk videodev mei_wdt irqbypass thinkpad_acpi snd_timer rapl think_lmi iTCO_wdt cfg80211 bluetooth iTCO_vendor_support intel_cstate snd videobuf2_common i2c_i801 firmware_attributes_class mei_me mc pcspkr intel_uncore wmi_bmof ledtrig_audio i2c_smbus mei soundcore lpc_ich platform_profile rfkill joydev xfs libcrc32c i915 i2c_algo_bit drm_buddy ttm intel_gtt drm_display_helper
[  618.993068]  drm_kms_helper sr_mod sd_mod cdrom t10_pi sg drm crct10dif_pclmul ahci crc32_pclmul sdhci_pci libahci crc32c_intel e1000e cqhci libata sdhci ghash_clmulni_intel mmc_core cec video wmi serio_raw dm_mirror dm_region_hash dm_log dm_mod fuse
[  618.993086] CPU: 2 PID: 8967 Comm: exe Kdump: loaded Tainted: G        W          6.8.0-rc7.sebastian-rt6+ #1
[  618.993089] Hardware name: LENOVO 427623U/427623U, BIOS 8BET45WW (1.25 ) 05/18/2011
[  618.993090] RIP: 0010:free_event+0x36/0x40
[  618.993093] Code: f0 48 0f b1 97 38 02 00 00 48 83 f8 01 75 05 e9 a0 fd ff ff 48 8b b7 38 02 00 00 48 89 fa 48 c7 c7 20 9c 1b ac e8 6a 52 dd ff <0f> 0b c3 cc cc cc cc 0f 1f 00 90 90 90 90 90 90 90 90 90 90 90 90
[  618.993095] RSP: 0018:ffffb81e83c8bd30 EFLAGS: 00010282
[  618.993097] RAX: 0000000000000000 RBX: dead000000000122 RCX: 0000000000000000
[  618.993099] RDX: 0000000000000002 RSI: ffffffffac1dcc6a RDI: 00000000ffffffff
[  618.993100] RBP: ffff93e8010799c8 R08: 0000000000000000 R09: ffffb81e83c8bb28
[  618.993102] R10: ffffb81e83c8bb20 R11: ffffffffacdefe48 R12: ffff93e80104e1f8
[  618.993103] R13: ffff93e82d021284 R14: ffffb81e83c8bad8 R15: dead000000000100
[  618.993104] FS:  0000000000000000(0000) GS:ffff93eb1e280000(0000) knlGS:0000000000000000
[  618.993106] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  618.993108] CR2: 00007ffce8826e40 CR3: 0000000116464004 CR4: 00000000000606f0
[  618.993110] Call Trace:
[  618.993111]  <TASK>
[  618.993113]  ? __warn+0x85/0x140
[  618.993116]  ? free_event+0x36/0x40
[  618.993118]  ? report_bug+0x1c3/0x1d0
[  618.993124]  ? handle_bug+0x3c/0x70
[  618.993127]  ? exc_invalid_op+0x14/0x70
[  618.993130]  ? asm_exc_invalid_op+0x16/0x20
[  618.993136]  ? free_event+0x36/0x40
[  618.993138]  perf_event_release_kernel+0x255/0x2f0
[  618.993142]  perf_release+0x11/0x20
[  618.993144]  __fput+0x96/0x2c0
[  618.993147]  task_work_run+0x59/0x90
[  618.993152]  get_signal+0x91/0x900
[  618.993156]  arch_do_signal_or_restart+0x25/0x100
[  618.993160]  ? do_execveat_common.isra.0+0x1ae/0x230
[  618.993164]  ? syscall_exit_work+0x103/0x130
[  618.993166]  syscall_exit_to_user_mode+0x1ae/0x1f0
[  618.993170]  do_syscall_64+0x90/0x170
[  618.993173]  ? do_user_addr_fault+0x31b/0x690
[  618.993177]  entry_SYSCALL_64_after_hwframe+0x6e/0x76
[  618.993180] RIP: 0033:0x7f573a46eed0
[  618.993185] Code: Unable to access opcode bytes at 0x7f573a46eea6.
[  618.993186] RSP: 002b:00007ffce8826e40 EFLAGS: 00000200 ORIG_RAX: 000000000000003b
[  618.993188] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[  618.993189] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[  618.993190] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[  618.993191] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[  618.993192] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[  618.993195]  </TASK>
[  618.993195] ---[ end trace 0000000000000000 ]---
[  619.727029] ------------[ cut here ]------------
[  619.727033] unexpected event refcount: 2; ptr=00000000b09e0f42
[  619.727042] WARNING: CPU: 2 PID: 9017 at kernel/events/core.c:5240 free_event+0x36/0x40
[  619.727048] Modules linked in: nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set nf_tables nfnetlink bnep sunrpc iwldvm intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp mac80211 snd_hda_codec_hdmi snd_ctl_led snd_hda_codec_conexant coretemp snd_hda_codec_generic kvm_intel snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi libarc4 snd_hda_codec kvm snd_hda_core iwlwifi snd_hwdep uvcvideo snd_seq uvc btusb snd_seq_device videobuf2_vmalloc btrtl snd_pcm videobuf2_memops btintel btbcm videobuf2_v4l2 btmtk videodev mei_wdt irqbypass thinkpad_acpi snd_timer rapl think_lmi iTCO_wdt cfg80211 bluetooth iTCO_vendor_support intel_cstate snd videobuf2_common i2c_i801 firmware_attributes_class mei_me mc pcspkr intel_uncore wmi_bmof ledtrig_audio i2c_smbus mei soundcore lpc_ich platform_profile rfkill joydev xfs libcrc32c i915 i2c_algo_bit drm_buddy ttm intel_gtt drm_display_helper
[  619.727102]  drm_kms_helper sr_mod sd_mod cdrom t10_pi sg drm crct10dif_pclmul ahci crc32_pclmul sdhci_pci libahci crc32c_intel e1000e cqhci libata sdhci ghash_clmulni_intel mmc_core cec video wmi serio_raw dm_mirror dm_region_hash dm_log dm_mod fuse
[  619.727119] CPU: 2 PID: 9017 Comm: exe Kdump: loaded Tainted: G        W          6.8.0-rc7.sebastian-rt6+ #1
[  619.727122] Hardware name: LENOVO 427623U/427623U, BIOS 8BET45WW (1.25 ) 05/18/2011
[  619.727123] RIP: 0010:free_event+0x36/0x40
[  619.727126] Code: f0 48 0f b1 97 38 02 00 00 48 83 f8 01 75 05 e9 a0 fd ff ff 48 8b b7 38 02 00 00 48 89 fa 48 c7 c7 20 9c 1b ac e8 6a 52 dd ff <0f> 0b c3 cc cc cc cc 0f 1f 00 90 90 90 90 90 90 90 90 90 90 90 90
[  619.727128] RSP: 0018:ffffb81e83d5bca8 EFLAGS: 00010282
[  619.727130] RAX: 0000000000000000 RBX: dead000000000122 RCX: 0000000000000000
[  619.727132] RDX: 0000000000000002 RSI: ffffffffac1dcc6a RDI: 00000000ffffffff
[  619.727133] RBP: ffff93e801023390 R08: 0000000000000000 R09: ffffb81e83d5baa0
[  619.727134] R10: ffffb81e83d5ba98 R11: ffffffffacdefe48 R12: ffff93e8010261f8
[  619.727136] R13: ffff93e8054b7d84 R14: ffffb81e83d5ba50 R15: dead000000000100
[  619.727137] FS:  0000000000000000(0000) GS:ffff93eb1e280000(0000) knlGS:0000000000000000
[  619.727139] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  619.727140] CR2: 00007ffe58ed17b9 CR3: 00000001058da003 CR4: 00000000000606f0
[  619.727142] Call Trace:
[  619.727143]  <TASK>
[  619.727145]  ? __warn+0x85/0x140
[  619.727148]  ? free_event+0x36/0x40
[  619.727150]  ? report_bug+0x1c3/0x1d0
[  619.727156]  ? handle_bug+0x3c/0x70
[  619.727159]  ? exc_invalid_op+0x14/0x70
[  619.727162]  ? asm_exc_invalid_op+0x16/0x20
[  619.727169]  ? free_event+0x36/0x40
[  619.727171]  ? free_event+0x36/0x40
[  619.727172]  perf_event_release_kernel+0x255/0x2f0
[  619.727176]  perf_release+0x11/0x20
[  619.727178]  __fput+0x96/0x2c0
[  619.727182]  task_work_run+0x59/0x90
[  619.727185]  get_signal+0x91/0x900
[  619.727190]  ? migrate_enable+0xaa/0xf0
[  619.727194]  arch_do_signal_or_restart+0x25/0x100
[  619.727197]  ? do_execveat_common.isra.0+0x1ae/0x230
[  619.727200]  ? syscall_exit_work+0x103/0x130
[  619.727202]  syscall_exit_to_user_mode+0x1ae/0x1f0
[  619.727206]  do_syscall_64+0x90/0x170
[  619.727209]  ? __count_memcg_events+0x60/0x100
[  619.727213]  ? mm_account_fault+0x6c/0x100
[  619.727217]  ? handle_mm_fault+0xd8/0x210
[  619.727220]  ? do_user_addr_fault+0x31b/0x690
[  619.727224]  entry_SYSCALL_64_after_hwframe+0x6e/0x76
[  619.727227] RIP: 0033:0x7ffb0bcffed0
[  619.727232] Code: Unable to access opcode bytes at 0x7ffb0bcffea6.
[  619.727233] RSP: 002b:00007ffe58ed14b0 EFLAGS: 00000200 ORIG_RAX: 000000000000003b
[  619.727236] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[  619.727237] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[  619.727238] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[  619.727239] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[  619.727240] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[  619.727242]  </TASK>
[  619.727243] ---[ end trace 0000000000000000 ]---
[acme@nine perf_events]$