From: "Steven Rostedt (Google)" <[email protected]>
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: [email protected]
Fixes: 9fe41efaca084 ("tracing: Add synth event generation test module")
Reported-by: Alexander Graf <[email protected]>
Signed-off-by: Steven Rostedt (Google) <[email protected]>
---
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
On Wed, 20 Dec 2023 11:15:25 -0500
Steven Rostedt <[email protected]> wrote:
> From: "Steven Rostedt (Google)" <[email protected]>
>
> 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) <[email protected]>
Thank you,
> Cc: [email protected]
> Fixes: 9fe41efaca084 ("tracing: Add synth event generation test module")
> Reported-by: Alexander Graf <[email protected]>
> Signed-off-by: Steven Rostedt (Google) <[email protected]>
> ---
> 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
>
--
Masami Hiramatsu (Google) <[email protected]>
Hi Steve,
On 20.12.23 17:15, Steven Rostedt wrote:
>
> From: "Steven Rostedt (Google)" <[email protected]>
>
> 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: [email protected]
> Fixes: 9fe41efaca084 ("tracing: Add synth event generation test module")
> Reported-by: Alexander Graf <[email protected]>
> Signed-off-by: Steven Rostedt (Google) <[email protected]>
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 <[email protected]>
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 <[email protected]> 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 <[email protected]>
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.