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

[Jason Baron]

On Wed, Oct 13, 2010 at 08:00:27PM -0400, Mathieu Desnoyers wrote:
> * Steven Rostedt (rostedt@xxxxxxxxxxx) 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
> 

right, the current syscall tracepoint code, is optimized for the 'off'
case, not the 'on' case. That is, when off, we add no additional
overhead to the syscall path. If we add 2 tracepoints per syscall we
are adding some cost even when disabled - to every syscall.

However, with the addition of the asm goto code, those concerns will
hopefully go away as Mathieu points out.

thanks,

-Jason
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/