Hi again,
I now have some benchmark results for two more tracers, lttng and
perf. Thanks to Mathieu for helping me with the lttng test.
To restate our objectives:
I hope this produces a fair comparison. I've detailed my steps below
for all of the tracers in case there are improvements to be made.
This is the code used for the getuid microbenchmark:
http://autotest.kernel.org/browser/trunk/client/tests/tracing_microbenchmark/src/getui...
The numbers below are the "on" minus "off" average results over at
least 10 runs each.
Results for amount of time to execute a tracepoint (includes previous results):
ktrace: 200ns (old)
ftrace: 224ns (old, w/ handcoded tracepoint, not syscall tracing)
lttng: 449ns (new)
perf: 1047ns (new)
Also interesting:
ftrace: 587ns (old, w/ syscall tracing)
This just shows that syscall tracing is much slower than a normal tracepoint.
The rest of this email is a lot of details about the benchmark runs
for each tracer.
I look forward to your feedback.
Thanks,
David Sharp
Here are the details of the steps for the two new results (lttng,
perf) first, and then some repeated details of the previous ftrace and
ktrace results.
LTTng
-----
I use lttng in flight-recorder mode to avoid the overhead of a reader
while tracing.
The benchmark was run with these versions:
- lttng kernel 0.233 based on v.2.6.36
+ the sys_getuid tracepoint patch [0]
- ltt-modules v0.19.1
+ a probe for sys_getuid [1]
- ltt-control v0.88
I ran the benchmark like this:
#setup:
modprobe ltt-trace-control
modprobe syscall-trace
/sys/kernel/debug/ltt/markers/kernel/sys_getuid/enable
#run:
for n in $(seq 10) ; do \
lttctl -C -w $PWD/$n \
-o channel.all.bufsize=$((8*1024*1024)) \
-o channel.all.overwrite=1 trace1 && \
getuid_microbench 100000 >> results.traced && \
lttctl -D -w $PWD/$n trace1 ; \
done
for n in $(seq 10) ; do \
getuid_microbench 100000 >> results.notrace ; \
done
Perf
----
This was run with a vanilla v2.6.36 kernel plus the sys_getuid
tracepoint patch, and perf 0.0.2. I used a large number of pages and
observed that perf reported it woke up only once to write data. I'm
assuming that it woke up at the end, so it was out of the way during
the tracing.
for n in $(seq 10) ; do \
perf record -e timer:sys_getuid -a -m 4096 -- \
getuid_microbench 100000 >> results.perf ; \
done
for n in $(seq 10) ; \
do getuid_microbench 100000 >> results.notrace ; \
done
ftrace
------
ftrace and ktrace benchmarks were run using Autotest. The commands
below approximate what the autotest does. The Autotest test itself is
here:
http://autotest.kernel.org/browser/trunk/client/tests/tracing_microbenchmark
#setup:
tracedir="/sys/kernel/debug/tracing"
echo '$((8*1024)) > $tracedir/buffer_size_kb
echo '1' > $tracedir/events/timer/sys_getuid/enable
#run:
for n in $(seq 10) ; do \
echo '1' > $tracing/tracing_enabled && \
getuid_microbench 100000 >> results.ftrace && \
echo '0' > $tracing/tracing_enabled && \
echo > $tracing/trace ; \
done
for n in $(seq 10) ; do \
getuid_microbench 100000 >> results.notrace && \
done
ktrace
------
I didn't push the ktrace tracer to the public kernel.org Autotest, but
it is quite similar to the ftrace tracer. Once again, I'll approximate
it with shell commands:
#setup:
tracedir="/sys/kernel/debug/ktrace"
echo '$((8*1024*1024)) > $tracedir/bufsize
echo '1' > $tracedir/events/kernel_getuid
#run:
for n in $(seq 10) ; do \
echo '1' > $tracing/enabled && \
getuid_microbench 100000 >> results.ftrace && \
echo '0' > $tracing/enabled && \
echo '1' > $tracing/reset ; \
done
for n in $(seq 10) ; do \
getuid_microbench 100000 >> results.notrace && \
done
Footnotes
---------
[0] sys_getuid tracepoint:
http://google3-2.osuosl.org/?p=kernel/tracing/ktrace.git;a=commitdiff;h=872088a6e482ce...
[1] sys_getuid ltt probe, diff against ltt-module v0.19.1 (forgive
gmail's patch mangling):
diff --git a/probes/syscall-trace.c b/probes/syscall-trace.c
index 9ae419f..1409a74 100644
--- a/probes/syscall-trace.c
+++ b/probes/syscall-trace.c
@@ -49,6 +49,20 @@ notrace void probe_syscall_exit(void *_data, long ret)
&ret, sizeof(ret), sizeof(ret));
}
+void probe_getuid(void *_data, uid_t uid);
+
+DEFINE_MARKER_TP(kernel, sys_getuid, sys_getuid,
+ probe_getuid, "uid %d");
+
+notrace void probe_getuid(void *_data, uid_t uid)
+{
+ struct marker *marker;
+
+ marker = &GET_MARKER(kernel, sys_getuid);
+ ltt_specialized_trace(marker, marker->single.probe_private,
+ &uid, sizeof(uid), sizeof(uid));
+}
+
MODULE_LICENSE("GPL and additional rights");
MODULE_AUTHOR("Mathieu Desnoyers");
MODULE_DESCRIPTION("syscall Tracepoint Probes");
--
1.7.1
--
