Re: Benchmarks of kernel tracing options (ftrace and ktrace)

[Frederic Weisbecker <fweisbec@gmail.com>]

On Wed, Oct 13, 2010 at 08:00:27PM -0400, Mathieu Desnoyers wrote:
> * Steven Rostedt (rostedt@goodmis.org) wrote:
> > On Wed, 2010-10-13 at 16:19 -0700, David Sharp wrote:
> > > Google uses kernel tracing aggressively in the its data centers. We
> > 
> > Thanks!
> > 
> > > wrote our own kernel tracer, ktrace. However ftrace, perf and LTTng
> > > all have a better feature set than ktrace, so we are abandoning that
> > > code.
> > 
> > Cool!
> > 
> > > 
> > > We see several implementations of tracing aimed at the mainline kernel
> > > and wanted a fair comparison of each of them to make sure they will
> > > not significantly impact performance. A tracing toolkit that is too
> > > expensive is not usable in our environment.
> > > 
> > 
> > [ snip for now (I'm traveling) ]
> > 
> > > This first set of benchmark results compares ftrace to ktrace. The
> > > numbers below are the "on" result minus the "off" result for each
> > > configuration.
> > > 
> > > ktrace: 200ns  (tracepoint: kernel_getuid)
> > > ftrace: 224ns   (tracepoint: timer:sys_getuid)
> > > ftrace: 587ns   (tracepoint: syscalls:sys_enter_getuid)
> > 
> > 
> > > The last result shows that the syscall tracing is about twice as
> > > expensive as a normal tracepoint, which is interesting.
> > 
> > Argh, the syscall tracing has a lot of overhead. There is only one
> > tracepoint that is hooked into the ptrace code, and will save all
> > registers before calling the functions. It enables tracing on all
> > syscalls and there's a table that decides whether or not to trace the
> > syscall.
> > 
> > So I'm not surprised with the result that the syscall trace point is so
> > slow (note, perf uses the same infrastructure).
> 
> Yes, the interesting result in this first set of benchmarks is that syscall
> tracing is quite slow. We could do better though. I think a different scheme
> for syscall tracing that would not rely of saving all registers is needed. We
> could do this automatically by adding tracepoints in the actual syscall
> functions by modifying the DEFINE_SYSCALL*() macros. I would leave the current
> syscall tracing mode as the default though, especially until gcc 4.5 and asm
> gotos are more broadly adopted.
> 
> So the modified DEFINE_SYSCALL*() macros would generate code that looks like:
> (approximately)
> 
> static int _syscall_name(type1, name1);
> 
> int syscall_name(type1 name1)
> {
>         int ret;
> 
>         trace_syscall_entry_name(name1);
>         ret = _syscall_name(name1);
>         trace_syscall_exit_name(name1);
>         return ret;
> }
> 
> static int _syscall_name(typê1, name1)
> 
> 
> So when we expand:
> 
> DEFINE_SYSCALL1(name, type1, name1)
> {
>   .. actual body ...
> }
> 
> We have the tracepoints automatically added.
> 
> Mathieu



Looks like that would be a good improvement, it would also
simplify some tricky code parts I think.