Trace event testing time - 3s to 41s

Trace event testing time - 3s to 41s

[Parag Warudkar]

Somewhere between -rc9 and yesterday's git, my desktop went from using
3s worth of trace event testing time to 41s !

It looks like we not only added a whole bunch of tracing points but
also are doing the tests twice post -rc9 - the addition being testing
with function tracer.

grep "Testing event" dmesg.31rc9 |wc -l
100

grep "Testing event" dmesg.31git |wc -l
1172

While one could get away with "don't enable that config option then"
response, for testing kernels daily this sounds like it is going to be
very annoying as it adds a considerable boot lag.

So I was thinking could we move this testing to a kthread with idle
priority or something - may be disabling tracing until those tests are
finished, if that sort of thing is necessary?
Or does it need to happen synchronous to booting?

Thanks

Parag

Re: Trace event testing time - 3s to 41s

[Steven Rostedt]

On Sun, 2009-09-13 at 11:15 -0400, Parag Warudkar wrote:
> Somewhere between -rc9 and yesterday's git, my desktop went from using
> 3s worth of trace event testing time to 41s !
> 
> It looks like we not only added a whole bunch of tracing points but
> also are doing the tests twice post -rc9 - the addition being testing
> with function tracer.
> 
> grep "Testing event" dmesg.31rc9 |wc -l
> 100
> 
> grep "Testing event" dmesg.31git |wc -l
> 1172

This was due to the fact that we test every syscall now.

> 
> While one could get away with "don't enable that config option then"
> response, for testing kernels daily this sounds like it is going to be
> very annoying as it adds a considerable boot lag.
> 
> So I was thinking could we move this testing to a kthread with idle
> priority or something - may be disabling tracing until those tests are
> finished, if that sort of thing is necessary?
> Or does it need to happen synchronous to booting?

I don't have time at the moment, but I would not mind moving the syscall
testing to a thread. Heck, that way we can actually test syscalls
too ;-)

-- Steve

[tip:tracing/core] tracing: make testing syscall events a separate configuration

[tip-bot for Steven Rostedt]

Commit-ID:  1f5a6b45416694ff8c0d04625f1a438a0e380add
Gitweb:     http://git.kernel.org/tip/1f5a6b45416694ff8c0d04625f1a438a0e380add
Author:     Steven Rostedt <srostedt@redhat.com>
AuthorDate: Mon, 14 Sep 2009 11:58:24 -0400
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Mon, 14 Sep 2009 11:58:24 -0400

tracing: make testing syscall events a separate configuration

Parag noticed that the number of event tests has increased tremendously:

grep "Testing event" dmesg.31rc9 |wc -l
100

grep "Testing event" dmesg.31git |wc -l
1172

This is due to the testing of every syscall event when ftrace self
test is enabled. This adds a bit more time to kernel boot up and can
affect development by slowing down the time it takes between reboots.

This option makes the testing of the syscall events into a separate
config, to still be able to test most of ftrace internals at boot up
but not have to wait for all the syscall events to be tested.

The syscall event testing only tests the enabling and disabling of
the trace point, since the syscalls are not executed. What really needs
to be done is to somehow have a userspace tool test the syscall tracepoints
as well.

Reported-by: Parag Warudkar <parag.lkml@gmail.com>
LKML-Reference: <f7848160909130815l3e768a30n3b28808bbe5c254b@mail.gmail.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>


---
 kernel/trace/Kconfig        |   12 ++++++++++++
 kernel/trace/trace_events.c |   12 ++++++++++++
 2 files changed, 24 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 1ea0d12..aa002ce 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -469,6 +469,18 @@ config FTRACE_STARTUP_TEST
 	  functioning properly. It will do tests on all the configured
 	  tracers of ftrace.
 
+config EVENT_TRACE_TEST_SYSCALLS
+	bool "Run selftest on syscall events"
+	depends on FTRACE_STARTUP_TEST
+	help
+	 This option will also enable testing every syscall event.
+	 It only enables the event and disables it and runs various loads
+	 with the event enabled. This adds a bit more time for kernel boot
+	 up since it runs this on every system call defined.
+
+	 TBD - enable a way to actually call the syscalls as we test their
+	       events
+
 config MMIOTRACE
 	bool "Memory mapped IO tracing"
 	depends on HAVE_MMIOTRACE_SUPPORT && PCI
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 0fa8f9f..787f0fb 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -1326,6 +1326,18 @@ static __init void event_trace_self_tests(void)
 		if (!call->regfunc)
 			continue;
 
+/*
+ * Testing syscall events here is pretty useless, but
+ * we still do it if configured. But this is time consuming.
+ * What we really need is a user thread to perform the
+ * syscalls as we test.
+ */
+#ifndef CONFIG_EVENT_TRACE_TEST_SYSCALLS
+		if (call->system &&
+		    strcmp(call->system, "syscalls") == 0)
+			continue;
+#endif
+
 		pr_info("Testing event %s: ", call->name);
 
 		/*