Warning when exiting osnoise tracer

Warning when exiting osnoise tracer

[Nicolas Saenz Julienne]

While running next-20220307, on a system with isolated CPUs (don't know if
relevant but less tested code-path), I see this after killing (ctrl-C) the
following trace command:

	trace-cmd record -e all -M 10 -p osnoise --poll

Note that this is *without* my recent osnoise patch.

[  129.925474] ------------[ cut here ]------------
[  129.926021] WARNING: CPU: 0 PID: 1217 at kernel/tracepoint.c:404 tracepoint_probe_unregister+0x280/0x370
[  129.927077] 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 rfkill ip_set nf_tables nfnetlink intel_rapl_msr intel_rapl_common irqbypass iTCO_wdt rapl snd_pcm iTCO_vendor_support snd_timer snd soundcore i2c_i801 lpc_ich i2c_smbus virtio_balloon pcspkr fuse drm xfs libcrc32c crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel ahci libahci serio_raw virtio_net libata net_failover failover virtio_blk
[  129.932263] CPU: 0 PID: 1217 Comm: trace-cmd Not tainted 5.17.0-rc6-next-20220307-nico+ #19
[  129.933184] Hardware name: Red Hat KVM/RHEL-AV, BIOS 1.15.0-1.el9 04/01/2014
[  129.933947] RIP: 0010:tracepoint_probe_unregister+0x280/0x370
[  129.934590] Code: 48 8d 04 40 48 8d 0c c3 48 8b 01 48 85 c0 74 21 49 39 c5 75 e5 4c 3b 71 08 75 df 48 c7 01 20 95 3e ae eb d6 41 bc fe ff ff ff <0f> 0b e9 22 ff ff ff 48 81 fb 00 f0 ff ff 0f 87 cb 00 00 00 45 31
[  129.936605] RSP: 0018:ffffb978c1093db8 EFLAGS: 00010246
[  129.937192] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[  129.937968] RDX: ffff8ee953ab8000 RSI: ffffffffae40cb20 RDI: ffffffffafc4c940
[  129.938752] RBP: ffffffffafd1c560 R08: 0000000000000000 R09: 0000000000000000
[  129.939537] R10: 0000000000000010 R11: 0000000000000000 R12: 00000000fffffffe
[  129.940323] R13: ffffffffae40cb20 R14: 0000000000000000 R15: 0000000000000003
[  129.941104] FS:  00007ff9198d1740(0000) GS:ffff8ee97ca00000(0000) knlGS:0000000000000000
[  129.941992] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  129.942633] CR2: 00007ff919b29497 CR3: 0000000109da4005 CR4: 0000000000170ef0
[  129.943420] Call Trace:
[  129.943714]  <TASK>
[  129.943960]  osnoise_workload_stop+0x36/0x90
[  129.944447]  tracing_set_tracer+0x108/0x260
[  129.944917]  tracing_set_trace_write+0x94/0xd0
[  129.945423]  ? __check_object_size.part.0+0x10a/0x150
[  129.945986]  ? selinux_file_permission+0x104/0x150
[  129.946531]  vfs_write+0xb5/0x290
[  129.946908]  ksys_write+0x5f/0xe0
[  129.947291]  do_syscall_64+0x3b/0x90
[  129.947693]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[  129.948257] RIP: 0033:0x7ff919a18127
[  129.948660] Code: 0b 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[  129.950688] RSP: 002b:00007ffe388ceda8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[  129.951530] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007ff919a18127
[  129.952355] RDX: 0000000000000003 RSI: 000000000044a514 RDI: 0000000000000004
[  129.953142] RBP: 00007ffe388cede0 R08: 0000000001cffd40 R09: 00007ff919a8a4e0
[  129.953917] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe388cf0c8
[  129.954692] R13: 000000000040a578 R14: 00007ff919b67aa0 R15: 0000000000461d18
[  129.955477]  </TASK>
[  129.955728] ---[ end trace 0000000000000000 ]---

Regards,

-- 
Nicolás Sáenz

Re: Warning when exiting osnoise tracer

[Daniel Bristot de Oliveira]

Hi Nicolas

On 3/8/22 18:30, Nicolas Saenz Julienne wrote:
> While running next-20220307, on a system with isolated CPUs (don't know if
> relevant but less tested code-path), I see this after killing (ctrl-C) the
> following trace command:
> 
> 	trace-cmd record -e all -M 10 -p osnoise --poll
> 
> Note that this is *without* my recent osnoise patch.

yeah, your patch does not hit this part of the code.

> [  129.925474] ------------[ cut here ]------------
> [  129.926021] WARNING: CPU: 0 PID: 1217 at kernel/tracepoint.c:404 tracepoint_probe_unregister+0x280/0x370
> [  129.927077] 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 rfkill ip_set nf_tables nfnetlink intel_rapl_msr intel_rapl_common irqbypass iTCO_wdt rapl snd_pcm iTCO_vendor_support snd_timer snd soundcore i2c_i801 lpc_ich i2c_smbus virtio_balloon pcspkr fuse drm xfs libcrc32c crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel ahci libahci serio_raw virtio_net libata net_failover failover virtio_blk
> [  129.932263] CPU: 0 PID: 1217 Comm: trace-cmd Not tainted 5.17.0-rc6-next-20220307-nico+ #19
> [  129.933184] Hardware name: Red Hat KVM/RHEL-AV, BIOS 1.15.0-1.el9 04/01/2014
> [  129.933947] RIP: 0010:tracepoint_probe_unregister+0x280/0x370
> [  129.934590] Code: 48 8d 04 40 48 8d 0c c3 48 8b 01 48 85 c0 74 21 49 39 c5 75 e5 4c 3b 71 08 75 df 48 c7 01 20 95 3e ae eb d6 41 bc fe ff ff ff <0f> 0b e9 22 ff ff ff 48 81 fb 00 f0 ff ff 0f 87 cb 00 00 00 45 31
> [  129.936605] RSP: 0018:ffffb978c1093db8 EFLAGS: 00010246
> [  129.937192] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
> [  129.937968] RDX: ffff8ee953ab8000 RSI: ffffffffae40cb20 RDI: ffffffffafc4c940
> [  129.938752] RBP: ffffffffafd1c560 R08: 0000000000000000 R09: 0000000000000000
> [  129.939537] R10: 0000000000000010 R11: 0000000000000000 R12: 00000000fffffffe
> [  129.940323] R13: ffffffffae40cb20 R14: 0000000000000000 R15: 0000000000000003
> [  129.941104] FS:  00007ff9198d1740(0000) GS:ffff8ee97ca00000(0000) knlGS:0000000000000000
> [  129.941992] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [  129.942633] CR2: 00007ff919b29497 CR3: 0000000109da4005 CR4: 0000000000170ef0
> [  129.943420] Call Trace:
> [  129.943714]  <TASK>
> [  129.943960]  osnoise_workload_stop+0x36/0x90

osnoise_workload_stop() is being called twice by trace-cmd. trace-cmd stops the
tracer, and then after that, it switches to nop. I did not cover this case when
I added the support for multiple instances (it is a tracer problem, not a
trace-cmd problem).

I am testing a fix already - fix for 5.16 on.

Thanks!
-- Daniel

> [  129.944447]  tracing_set_tracer+0x108/0x260
> [  129.944917]  tracing_set_trace_write+0x94/0xd0
> [  129.945423]  ? __check_object_size.part.0+0x10a/0x150
> [  129.945986]  ? selinux_file_permission+0x104/0x150
> [  129.946531]  vfs_write+0xb5/0x290
> [  129.946908]  ksys_write+0x5f/0xe0
> [  129.947291]  do_syscall_64+0x3b/0x90
> [  129.947693]  entry_SYSCALL_64_after_hwframe+0x44/0xae
> [  129.948257] RIP: 0033:0x7ff919a18127
> [  129.948660] Code: 0b 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
> [  129.950688] RSP: 002b:00007ffe388ceda8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
> [  129.951530] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007ff919a18127
> [  129.952355] RDX: 0000000000000003 RSI: 000000000044a514 RDI: 0000000000000004
> [  129.953142] RBP: 00007ffe388cede0 R08: 0000000001cffd40 R09: 00007ff919a8a4e0
> [  129.953917] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe388cf0c8
> [  129.954692] R13: 000000000040a578 R14: 00007ff919b67aa0 R15: 0000000000461d18
> [  129.955477]  </TASK>
> [  129.955728] ---[ end trace 0000000000000000 ]---
> 
> Regards,
> 

Re: Warning when exiting osnoise tracer

[Steven Rostedt]

On Wed, 9 Mar 2022 08:25:56 +0100
Daniel Bristot de Oliveira <bristot@kernel.org> wrote:

> On 3/8/22 18:30, Nicolas Saenz Julienne wrote:
> > While running next-20220307, on a system with isolated CPUs (don't know if
> > relevant but less tested code-path), I see this after killing (ctrl-C) the
> > following trace command:
> > 
> > 	trace-cmd record -e all -M 10 -p osnoise --poll
> > 
> > Note that this is *without* my recent osnoise patch.  
> 
> yeah, your patch does not hit this part of the code.
> 
> > [  129.925474] ------------[ cut here ]------------

I'm surprised that my tests did not hit this.

I've been running a lot of trace-cmd tests lately (to try and release 3.0!)
and I have osnoise tracer enabled in these tests.

Hmm, it's just a warning that doesn't appear to cause any damage. I just
tried it out, and sure enough it triggered. The problem is that my
trace-cmd tests do not check dmesg :-/  Maybe I need to change that, as I
only looked at the result of the test, and because the tests spits out a
lot of noise to dmesg, I can easily miss warnings there. I'll add a test to
look for Call Traces at the end of the test.

Thanks for the report.

-- Steve

Re: Warning when exiting osnoise tracer

[Steven Rostedt]

On Wed, 9 Mar 2022 10:54:03 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> lot of noise to dmesg, I can easily miss warnings there. I'll add a test to
> look for Call Traces at the end of the test.

My tests now detect this :-)

I tried it out on the current kernel, and it now gives me a failure if one
of the tests trigger a WARN_ON in the kernel. Which the test that runs a
record against every tracer, including osnoise, just failed on.

-- Steve