| Message ID | 20231220111525.2f0f49b0@gandalf.local.home (mailing list archive) |
|---|---|
| State | Accepted |
| Commit | 88b30c7f5d27e1594d70dc2bd7199b18f2b57fa9 |
| Headers | show |
| Series | tracing / synthetic: Disable events after testing in synth_event_gen_test_init() | expand |
On Wed, 20 Dec 2023 11:15:25 -0500 Steven Rostedt <rostedt@goodmis.org> wrote: > From: "Steven Rostedt (Google)" <rostedt@goodmis.org> > > The synth_event_gen_test module can be built in, if someone wants to run > the tests at boot up and not have to load them. > > The synth_event_gen_test_init() function creates and enables the synthetic > events and runs its tests. > > The synth_event_gen_test_exit() disables the events it created and > destroys the events. > > If the module is builtin, the events are never disabled. The issue is, the > events should be disable after the tests are run. This could be an issue > if the rest of the boot up tests are enabled, as they expect the events to > be in a known state before testing. That known state happens to be > disabled. > > When CONFIG_SYNTH_EVENT_GEN_TEST=y and CONFIG_EVENT_TRACE_STARTUP_TEST=y > a warning will trigger: > > Running tests on trace events: > Testing event create_synth_test: > Enabled event during self test! > ------------[ cut here ]------------ > WARNING: CPU: 2 PID: 1 at kernel/trace/trace_events.c:4150 event_trace_self_tests+0x1c2/0x480 > Modules linked in: > CPU: 2 PID: 1 Comm: swapper/0 Not tainted 6.7.0-rc2-test-00031-gb803d7c664d5-dirty #276 > Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-debian-1.16.2-1 04/01/2014 > RIP: 0010:event_trace_self_tests+0x1c2/0x480 > Code: bb e8 a2 ab 5d fc 48 8d 7b 48 e8 f9 3d 99 fc 48 8b 73 48 40 f6 c6 01 0f 84 d6 fe ff ff 48 c7 c7 20 b6 ad bb e8 7f ab 5d fc 90 <0f> 0b 90 48 89 df e8 d3 3d 99 fc 48 8b 1b 4c 39 f3 0f 85 2c ff ff > RSP: 0000:ffffc9000001fdc0 EFLAGS: 00010246 > RAX: 0000000000000029 RBX: ffff88810399ca80 RCX: 0000000000000000 > RDX: 0000000000000000 RSI: ffffffffb9f19478 RDI: ffff88823c734e64 > RBP: ffff88810399f300 R08: 0000000000000000 R09: fffffbfff79eb32a > R10: ffffffffbcf59957 R11: 0000000000000001 R12: ffff888104068090 > R13: ffffffffbc89f0a0 R14: ffffffffbc8a0f08 R15: 0000000000000078 > FS: 0000000000000000(0000) GS:ffff88823c700000(0000) knlGS:0000000000000000 > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > CR2: 0000000000000000 CR3: 00000001f6282001 CR4: 0000000000170ef0 > Call Trace: > <TASK> > ? __warn+0xa5/0x200 > ? event_trace_self_tests+0x1c2/0x480 > ? report_bug+0x1f6/0x220 > ? handle_bug+0x6f/0x90 > ? exc_invalid_op+0x17/0x50 > ? asm_exc_invalid_op+0x1a/0x20 > ? tracer_preempt_on+0x78/0x1c0 > ? event_trace_self_tests+0x1c2/0x480 > ? __pfx_event_trace_self_tests_init+0x10/0x10 > event_trace_self_tests_init+0x27/0xe0 > do_one_initcall+0xd6/0x3c0 > ? __pfx_do_one_initcall+0x10/0x10 > ? kasan_set_track+0x25/0x30 > ? rcu_is_watching+0x38/0x60 > kernel_init_freeable+0x324/0x450 > ? __pfx_kernel_init+0x10/0x10 > kernel_init+0x1f/0x1e0 > ? _raw_spin_unlock_irq+0x33/0x50 > ret_from_fork+0x34/0x60 > ? __pfx_kernel_init+0x10/0x10 > ret_from_fork_asm+0x1b/0x30 > </TASK> > > This is because the synth_event_gen_test_init() left the synthetic events > that it created enabled. By having it disable them after testing, the > other selftests will run fine. > Ah, OK. It has to clean up the testing events. Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org> Thank you, > Cc: stable@vger.kernel.org > Fixes: 9fe41efaca084 ("tracing: Add synth event generation test module") > Reported-by: Alexander Graf <graf@amazon.com> > Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> > --- > kernel/trace/synth_event_gen_test.c | 11 +++++++++++ > 1 file changed, 11 insertions(+) > > diff --git a/kernel/trace/synth_event_gen_test.c b/kernel/trace/synth_event_gen_test.c > index 8dfe85499d4a..354c2117be43 100644 > --- a/kernel/trace/synth_event_gen_test.c > +++ b/kernel/trace/synth_event_gen_test.c > @@ -477,6 +477,17 @@ static int __init synth_event_gen_test_init(void) > > ret = test_trace_synth_event(); > WARN_ON(ret); > + > + /* Disable when done */ > + trace_array_set_clr_event(gen_synth_test->tr, > + "synthetic", > + "gen_synth_test", false); > + trace_array_set_clr_event(empty_synth_test->tr, > + "synthetic", > + "empty_synth_test", false); > + trace_array_set_clr_event(create_synth_test->tr, > + "synthetic", > + "create_synth_test", false); > out: > return ret; > } > -- > 2.42.0 >
Hi Steve, On 20.12.23 17:15, Steven Rostedt wrote: > > From: "Steven Rostedt (Google)" <rostedt@goodmis.org> > > The synth_event_gen_test module can be built in, if someone wants to run > the tests at boot up and not have to load them. > > The synth_event_gen_test_init() function creates and enables the synthetic > events and runs its tests. > > The synth_event_gen_test_exit() disables the events it created and > destroys the events. > > If the module is builtin, the events are never disabled. The issue is, the > events should be disable after the tests are run. This could be an issue > if the rest of the boot up tests are enabled, as they expect the events to > be in a known state before testing. That known state happens to be > disabled. > > When CONFIG_SYNTH_EVENT_GEN_TEST=y and CONFIG_EVENT_TRACE_STARTUP_TEST=y > a warning will trigger: > > Running tests on trace events: > Testing event create_synth_test: > Enabled event during self test! > ------------[ cut here ]------------ > WARNING: CPU: 2 PID: 1 at kernel/trace/trace_events.c:4150 event_trace_self_tests+0x1c2/0x480 > Modules linked in: > CPU: 2 PID: 1 Comm: swapper/0 Not tainted 6.7.0-rc2-test-00031-gb803d7c664d5-dirty #276 > Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-debian-1.16.2-1 04/01/2014 > RIP: 0010:event_trace_self_tests+0x1c2/0x480 > Code: bb e8 a2 ab 5d fc 48 8d 7b 48 e8 f9 3d 99 fc 48 8b 73 48 40 f6 c6 01 0f 84 d6 fe ff ff 48 c7 c7 20 b6 ad bb e8 7f ab 5d fc 90 <0f> 0b 90 48 89 df e8 d3 3d 99 fc 48 8b 1b 4c 39 f3 0f 85 2c ff ff > RSP: 0000:ffffc9000001fdc0 EFLAGS: 00010246 > RAX: 0000000000000029 RBX: ffff88810399ca80 RCX: 0000000000000000 > RDX: 0000000000000000 RSI: ffffffffb9f19478 RDI: ffff88823c734e64 > RBP: ffff88810399f300 R08: 0000000000000000 R09: fffffbfff79eb32a > R10: ffffffffbcf59957 R11: 0000000000000001 R12: ffff888104068090 > R13: ffffffffbc89f0a0 R14: ffffffffbc8a0f08 R15: 0000000000000078 > FS: 0000000000000000(0000) GS:ffff88823c700000(0000) knlGS:0000000000000000 > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > CR2: 0000000000000000 CR3: 00000001f6282001 CR4: 0000000000170ef0 > Call Trace: > <TASK> > ? __warn+0xa5/0x200 > ? event_trace_self_tests+0x1c2/0x480 > ? report_bug+0x1f6/0x220 > ? handle_bug+0x6f/0x90 > ? exc_invalid_op+0x17/0x50 > ? asm_exc_invalid_op+0x1a/0x20 > ? tracer_preempt_on+0x78/0x1c0 > ? event_trace_self_tests+0x1c2/0x480 > ? __pfx_event_trace_self_tests_init+0x10/0x10 > event_trace_self_tests_init+0x27/0xe0 > do_one_initcall+0xd6/0x3c0 > ? __pfx_do_one_initcall+0x10/0x10 > ? kasan_set_track+0x25/0x30 > ? rcu_is_watching+0x38/0x60 > kernel_init_freeable+0x324/0x450 > ? __pfx_kernel_init+0x10/0x10 > kernel_init+0x1f/0x1e0 > ? _raw_spin_unlock_irq+0x33/0x50 > ret_from_fork+0x34/0x60 > ? __pfx_kernel_init+0x10/0x10 > ret_from_fork_asm+0x1b/0x30 > </TASK> > > This is because the synth_event_gen_test_init() left the synthetic events > that it created enabled. By having it disable them after testing, the > other selftests will run fine. > > Cc: stable@vger.kernel.org > Fixes: 9fe41efaca084 ("tracing: Add synth event generation test module") > Reported-by: Alexander Graf <graf@amazon.com> > Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> Thanks a bunch for the super quick turnaround time for the fix! I can confirm that I'm no longer seeing the warning :) Tested-by: Alexander Graf <graf@amazon.com> Do we need another similar patch for the kprobe self tests? The below is with 55cb5f43689d7 plus an unrelated initrd patch plus this patch and the following .config: http://csgraf.de/tmp2/config-ftrace.xz [ 919.717134] Testing all events: OK [ 924.418194] Testing ftrace filter: OK [ 924.418887] trace_kprobe: Testing kprobe tracing: [ 924.424244] ------------[ cut here ]------------ [ 924.424952] WARNING: CPU: 2 PID: 1 at kernel/trace/trace_kprobe.c:2073 kprobe_trace_self_tests_init+0x192/0x540 [ 924.425659] Modules linked in: [ 924.425886] CPU: 2 PID: 1 Comm: swapper/0 Not tainted 6.7.0-rc6-00024-gc10698ad3c9a #298 [ 924.426448] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.2-0-gea1b7a073390-prebuilt.qemu.org 04/01/2014 [ 924.427230] RIP: 0010:kprobe_trace_self_tests_init+0x192/0x540 [ 924.427639] Code: 7e 10 74 3b 48 8b 36 48 39 d6 75 f2 0f 0b 48 c7 c7 58 71 79 a5 e8 ee 3e 5a fe 48 c7 c7 20 38 b7 a5 e8 a2 51 68 fe 85 c0 74 33 <0f> 0b 48 c7 c7 38 73 79 a5 e8 d0 3e 5a fe e8 4b 64 62 fe eb 23 48 [ 924.428922] RSP: 0000:ffffab508001be58 EFLAGS: 00010286 [ 924.429288] RAX: 00000000fffffff0 RBX: 000000000000005a RCX: 0000000000000202 [ 924.429800] RDX: 0000000000000000 RSI: 000000000002e970 RDI: ffffffffa5b708a0 [ 924.430295] RBP: 0000000000000000 R08: 0000000000000001 R09: ffffffffa4855a90 [ 924.430794] R10: 0000000000000007 R11: 000000000000028a R12: 0000000000000001 [ 924.431286] R13: ffffffffa5cc9a00 R14: ffff8cec81bebe00 R15: ffffffffa619f0f0 [ 924.431785] FS: 0000000000000000(0000) GS:ffff8cecf9100000(0000) knlGS:0000000000000000 [ 924.432346] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 924.432748] CR2: 0000000000000000 CR3: 000000004883e001 CR4: 00000000003706f0 [ 924.433246] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 924.433739] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [ 924.434233] Call Trace: [ 924.434418] <TASK> [ 924.434569] ? __warn+0x7d/0x140 [ 924.434807] ? kprobe_trace_self_tests_init+0x192/0x540 [ 924.435172] ? report_bug+0xf8/0x1e0 [ 924.435430] ? handle_bug+0x3f/0x70 [ 924.435677] ? exc_invalid_op+0x13/0x60 [ 924.435954] ? asm_exc_invalid_op+0x16/0x20 [ 924.436249] ? rdinit_setup+0x40/0x40 [ 924.436509] ? trace_kprobe_release+0x70/0xb0 [ 924.436822] ? kprobe_trace_self_tests_init+0x192/0x540 [ 924.437189] ? kprobe_trace_self_tests_init+0x421/0x540 [ 924.437551] ? init_kprobe_trace+0x1b0/0x1b0 [ 924.437855] do_one_initcall+0x44/0x200 [ 924.438131] kernel_init_freeable+0x1e8/0x330 [ 924.438439] ? rest_init+0xd0/0xd0 [ 924.438682] kernel_init+0x16/0x130 [ 924.438943] ret_from_fork+0x30/0x50 [ 924.439202] ? rest_init+0xd0/0xd0 [ 924.439445] ret_from_fork_asm+0x11/0x20 [ 924.439734] </TASK> [ 924.439893] ---[ end trace 0000000000000000 ]--- [ 924.440217] trace_kprobe: error on cleaning up probes. [ 924.440575] NG: Some tests are failed. Please check them. Alex Amazon Development Center Germany GmbH Krausenstr. 38 10117 Berlin Geschaeftsfuehrung: Christian Schlaeger, Jonathan Weiss Eingetragen am Amtsgericht Charlottenburg unter HRB 149173 B Sitz: Berlin Ust-ID: DE 289 237 879
On Thu, 21 Dec 2023 11:06:38 +0100 Alexander Graf <graf@amazon.com> wrote: > Thanks a bunch for the super quick turnaround time for the fix! I can > confirm that I'm no longer seeing the warning :) > > Tested-by: Alexander Graf <graf@amazon.com> Thanks Alex, > > > Do we need another similar patch for the kprobe self tests? The below is > with 55cb5f43689d7 plus an unrelated initrd patch plus this patch and > the following .config: http://csgraf.de/tmp2/config-ftrace.xz Sure, now you tell me ;-) I just finished all my tests and will be sending Linus a pull request soon. I'll let Masami handle this one, as it's under his department. -- Steve > > [ 919.717134] Testing all events: OK > [ 924.418194] Testing ftrace filter: OK > [ 924.418887] trace_kprobe: Testing kprobe tracing: > [ 924.424244] ------------[ cut here ]------------ > [ 924.424952] WARNING: CPU: 2 PID: 1 at > kernel/trace/trace_kprobe.c:2073 kprobe_trace_self_tests_init+0x192/0x540 > [ 924.425659] Modules linked in: > [ 924.425886] CPU: 2 PID: 1 Comm: swapper/0 Not tainted > 6.7.0-rc6-00024-gc10698ad3c9a #298 > [ 924.426448] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS > rel-1.16.2-0-gea1b7a073390-prebuilt.qemu.org 04/01/2014 > [ 924.427230] RIP: 0010:kprobe_trace_self_tests_init+0x192/0x540 > [ 924.427639] Code: 7e 10 74 3b 48 8b 36 48 39 d6 75 f2 0f 0b 48 c7 c7 > 58 71 79 a5 e8 ee 3e 5a fe 48 c7 c7 20 38 b7 a5 e8 a2 51 68 fe 85 c0 74 > 33 <0f> 0b 48 c7 c7 38 73 79 a5 e8 d0 3e 5a fe e8 4b 64 62 fe eb 23 48 > [ 924.428922] RSP: 0000:ffffab508001be58 EFLAGS: 00010286 > [ 924.429288] RAX: 00000000fffffff0 RBX: 000000000000005a RCX: > 0000000000000202 > [ 924.429800] RDX: 0000000000000000 RSI: 000000000002e970 RDI: > ffffffffa5b708a0 > [ 924.430295] RBP: 0000000000000000 R08: 0000000000000001 R09: > ffffffffa4855a90 > [ 924.430794] R10: 0000000000000007 R11: 000000000000028a R12: > 0000000000000001 > [ 924.431286] R13: ffffffffa5cc9a00 R14: ffff8cec81bebe00 R15: > ffffffffa619f0f0 > [ 924.431785] FS: 0000000000000000(0000) GS:ffff8cecf9100000(0000) > knlGS:0000000000000000 > [ 924.432346] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 924.432748] CR2: 0000000000000000 CR3: 000000004883e001 CR4: > 00000000003706f0 > [ 924.433246] DR0: 0000000000000000 DR1: 0000000000000000 DR2: > 0000000000000000 > [ 924.433739] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: > 0000000000000400 > [ 924.434233] Call Trace: > [ 924.434418] <TASK> > [ 924.434569] ? __warn+0x7d/0x140 > [ 924.434807] ? kprobe_trace_self_tests_init+0x192/0x540 > [ 924.435172] ? report_bug+0xf8/0x1e0 > [ 924.435430] ? handle_bug+0x3f/0x70 > [ 924.435677] ? exc_invalid_op+0x13/0x60 > [ 924.435954] ? asm_exc_invalid_op+0x16/0x20 > [ 924.436249] ? rdinit_setup+0x40/0x40 > [ 924.436509] ? trace_kprobe_release+0x70/0xb0 > [ 924.436822] ? kprobe_trace_self_tests_init+0x192/0x540 > [ 924.437189] ? kprobe_trace_self_tests_init+0x421/0x540 > [ 924.437551] ? init_kprobe_trace+0x1b0/0x1b0 > [ 924.437855] do_one_initcall+0x44/0x200 > [ 924.438131] kernel_init_freeable+0x1e8/0x330 > [ 924.438439] ? rest_init+0xd0/0xd0 > [ 924.438682] kernel_init+0x16/0x130 > [ 924.438943] ret_from_fork+0x30/0x50 > [ 924.439202] ? rest_init+0xd0/0xd0 > [ 924.439445] ret_from_fork_asm+0x11/0x20 > [ 924.439734] </TASK> > [ 924.439893] ---[ end trace 0000000000000000 ]--- > [ 924.440217] trace_kprobe: error on cleaning up probes. > [ 924.440575] NG: Some tests are failed. Please check them.
diff --git a/kernel/trace/synth_event_gen_test.c b/kernel/trace/synth_event_gen_test.c index 8dfe85499d4a..354c2117be43 100644 --- a/kernel/trace/synth_event_gen_test.c +++ b/kernel/trace/synth_event_gen_test.c @@ -477,6 +477,17 @@ static int __init synth_event_gen_test_init(void) ret = test_trace_synth_event(); WARN_ON(ret); + + /* Disable when done */ + trace_array_set_clr_event(gen_synth_test->tr, + "synthetic", + "gen_synth_test", false); + trace_array_set_clr_event(empty_synth_test->tr, + "synthetic", + "empty_synth_test", false); + trace_array_set_clr_event(create_synth_test->tr, + "synthetic", + "create_synth_test", false); out: return ret; }