[lttng-dev] Tracepoints overhead in x86_64

[lttng-dev] Tracepoints overhead in x86_64

[Gianluca Borello]

Hello,

This question is more focused on tracepoints rather than LTTng, so feel
free to point me at LKML if I'm too off topic.

I am looking for a way to trace all the system call activity 24/7 (and do
some very customized processing, so LTTng doesn't fit very well in the
picture), and I have the specific requirement that the overhead must be
extremely slow, even in the worst case.

Being a LTTng user myself, I figured tracepoints would be the first natural
choice, so what I did was writing a small kernel module that does nothing
but registering an empty probe for "sys_enter" and "sys_exit", and I am a
bit concerned about the results that I obtained on my Intel Core i3 running
linux 3.8.0.

Basically this is my worst case:

while(1)
{
close(5000);
}

I let this run for 10 seconds, and these are the numbers that I get:

- without tracepoints: 13.1M close/s
- with tracepoints: 4.1M close/s

The overhead is far from being negligible, and digging into the problem it
seems like when the tracepoints are enabled, the system doesn't go through
the "system_call_fastpath" (in arch/x86/kernel/entry_64.S), using IRET
instead of SYSRET (A relevant commit seems this:
https://github.com/torvalds/linux/commit/7bf36bbc5e0c09271f9efe22162f8cc3f8ebd3d2
).

This is the first time I look into these things so understanding the logic
behind is pretty hard for me, but I managed to write a quick and dirty hack
that just forces a call to "trace_sys_enter" and "trace_sys_exit" in the
fast path (you can find the patch attached, I didn't have a lot of time to
spend on this so it's pretty inefficient because I do a bunch of
instructions even if the tracepoints are not enabled and there are obvious
bugs if the ptrace code gets enabled, but it proves my point) and these are
the results:

- without tracepoints (patched kernel): 11.5M close()/s
- with tracepoints (patched kernel): 9.6M close()/s

Of course my benchmark is an extreme situation, but measuring in a more
realistic scenario (using apache ab to stress a nginx server) I can still
notice a difference:

- without tracepoints: 16K HTTP requests/s
- with tracepoints: 15.1K HTTP requests/s
- without tracepoints (patched kernel): 16K HTTP requests/s
- with tracepoints (patched kernel): 15.8K HTTP requests/s

It's a real 6% vs 1% worst case overhead when using an intense server
application, and that doesn't count the cost of executing the body of the
probes themselves.

Has anyone ever faced this before? Am I just inexperienced with the topic
and stating the obvious? Are there any suggestions or documentation I
should look at?

Thank you for your help and for the amazing work on LTTng.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20130830/6afcc27d/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: tracepoints_fast_syscall_path.patch
Type: application/octet-stream
Size: 3093 bytes
Desc: not available
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20130830/6afcc27d/attachment-0001.obj>

[lttng-dev] Tracepoints overhead in x86_64

[Mathieu Desnoyers]

* Gianluca Borello (g.borello at gmail.com) wrote:
> Hello,
> 
> This question is more focused on tracepoints rather than LTTng, so feel
> free to point me at LKML if I'm too off topic.
> 
> I am looking for a way to trace all the system call activity 24/7 (and do
> some very customized processing, so LTTng doesn't fit very well in the
> picture), and I have the specific requirement that the overhead must be
> extremely slow, even in the worst case.

extremely "low" I guess ;-)

> 
> Being a LTTng user myself, I figured tracepoints would be the first natural
> choice, so what I did was writing a small kernel module that does nothing
> but registering an empty probe for "sys_enter" and "sys_exit", and I am a
> bit concerned about the results that I obtained on my Intel Core i3 running
> linux 3.8.0.
> 
> Basically this is my worst case:
> 
> while(1)
> {
> close(5000);
> }
> 
> I let this run for 10 seconds, and these are the numbers that I get:
> 
> - without tracepoints: 13.1M close/s
> - with tracepoints: 4.1M close/s

First thing: this is really "system call tracepoints", and not the
tracepoint mechanism per se. (kernel option:
CONFIG_HAVE_SYSCALL_TRACEPOINTS if available on the architecture). We
cannot blame the tracepoints overall for the system call tracepoints,
since those are two very different instrumentation mechanisms.

> 
> The overhead is far from being negligible, and digging into the problem it
> seems like when the tracepoints are enabled, the system doesn't go through
> the "system_call_fastpath" (in arch/x86/kernel/entry_64.S), using IRET
> instead of SYSRET (A relevant commit seems this:
> https://github.com/torvalds/linux/commit/7bf36bbc5e0c09271f9efe22162f8cc3f8ebd3d2
> ).

indeed, I suspect this can have a big impact on performances.

> 
> This is the first time I look into these things so understanding the logic
> behind is pretty hard for me, but I managed to write a quick and dirty hack
> that just forces a call to "trace_sys_enter" and "trace_sys_exit" in the
> fast path (you can find the patch attached, I didn't have a lot of time to
> spend on this so it's pretty inefficient because I do a bunch of
> instructions even if the tracepoints are not enabled and there are obvious
> bugs if the ptrace code gets enabled, but it proves my point) and these are
> the results:
> 
> - without tracepoints (patched kernel): 11.5M close()/s
> - with tracepoints (patched kernel): 9.6M close()/s
> 
> Of course my benchmark is an extreme situation, but measuring in a more
> realistic scenario (using apache ab to stress a nginx server) I can still
> notice a difference:
> 
> - without tracepoints: 16K HTTP requests/s
> - with tracepoints: 15.1K HTTP requests/s
> - without tracepoints (patched kernel): 16K HTTP requests/s
> - with tracepoints (patched kernel): 15.8K HTTP requests/s
> 
> It's a real 6% vs 1% worst case overhead when using an intense server
> application, and that doesn't count the cost of executing the body of the
> probes themselves.
> 
> Has anyone ever faced this before? Am I just inexperienced with the topic
> and stating the obvious? Are there any suggestions or documentation I
> should look at?

A bit of history: you will notice that system call tracepoints are based
on the same function that is used when ptrace, system call audit,
seccomp are enabled for a given thread: these are all considered a slow
path, therefore, the utterly optimized case is when those features are
_not_ enabled, at the expense of extra overhead when they are enabled.

The basic mechanism is to test for a set of flags, and jump to a slow
path in entry*.S, which saves extra registers and calls an extra
function (syscall_trace_enter, syscall_trace_leave) at system call entry
and exit.

My recommendation would be to implement a dummy trace_sys_enter and
trace_sys_exit, and then benchmark the overhead of enabling system call
tracing (this will set TIF_SYSCALL_TRACEPOINT in every thread). So at
least it would help you pinpoint where most of the overhead comes from.

Indeed, if you come up with ways to shrink the overhead of this "slow
path", I'm sure the LTTng community would gladly welcome this. Of
course, these changes would have to be proposed to the Linux kernel
community. You will need to keep in mind that they will frown upon
pretty much _any_ slowdown of the fast path (common case, no tracing)
for improving the speed of the slow (uncommon) case.

> 
> Thank you for your help and for the amazing work on LTTng.

You're welcome! I'm glad you like it!

Mathieu


> _______________________________________________
> lttng-dev mailing list
> lttng-dev at lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev


-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

[lttng-dev] Tracepoints overhead in x86_64

[Gianluca Borello]

On Aug 31, 2013 1:21 PM, "Mathieu Desnoyers" <mathieu.desnoyers at efficios.com>
wrote:
>
> My recommendation would be to implement a dummy trace_sys_enter and
> trace_sys_exit, and then benchmark the overhead of enabling system call
> tracing (this will set TIF_SYSCALL_TRACEPOINT in every thread). So at
> least it would help you pinpoint where most of the overhead comes from.
>

Yes, I already did that before writing the patch I attached in the previous
mail, and I can confirm that simply setting  TIF_SYSCALL_TRACEPOINT in all
threads (without registering any tracepoint) shows the same overhead.

> Indeed, if you come up with ways to shrink the overhead of this "slow
> path", I'm sure the LTTng community would gladly welcome this. Of
> course, these changes would have to be proposed to the Linux kernel
> community. You will need to keep in mind that they will frown upon
> pretty much _any_ slowdown of the fast path (common case, no tracing)
> for improving the speed of the slow (uncommon) case.
>

That might be interesting.
I guess I have a couple of questions:

1) Where do you think I could find an answer to the question "can
trace_sys_enter be safely called from the fast path?". In my tests it
worked just fine, but I'm concerned that calling the tracepoint without
using the IRET slow path could lead to the potential DoS the commit was
fixing.

2) How do you think the kernel community would react to a patch that adds
the tracepoint call to the fast path? Basically, if it works, I'd check the
TIF_SYSCALL_TRACEPOINT directly in the fast path and, if set, I would
proceed in saving the registers and calling the probes, so in the common
case there would be just one more check against the current thread's flags.

Thank you again!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20130831/740f30f1/attachment.html>