Re: [PATCH 5/5] tracing/ftrace: Introduce the big kernel lock tracer

Re: [PATCH 5/5] tracing/ftrace: Introduce the big kernel lock tracer

[Frank Ch. Eigler]

>> Introduce the Big Kernel Lock tracer.
>> This new tracer lets one to observe the latencies caused
>> by the lock_kernel() function.
>> It captures the time when the task request the spinlock,
>> the time when the spinlock is hold and the time it is released.
>> This way we can measure the latency for a task that wait for this
>> spinlock and the latency caused by the time this lock is hold.

For comparison, this is how this sort of analysis may be done with
systemtap, just for fun collecting locking latency on a
per-locker/unlocker (stack traceback) basis.  We don't have the stack
traceback extended right into userspace yet, but will before too long.


% cat bkl.stp
probe kernel.function("lock_kernel") {
        locker=backtrace()
        locktime=gettimeofday_us()
}

probe kernel.function("lock_kernel").return {
        unlocktime=gettimeofday_us()
        delay = unlocktime-locktime
        lockhistory[locker,unlocker] <<< delay
}

probe kernel.function("unlock_kernel") {
        unlocker=backtrace()
}

global locker, unlocker, locktime, lockhistory

probe end,timer.s(30) { // interrupt any time; automatic ending in 30s
        foreach ([l,u] in lockhistory+) { // in increasing order of @count()

                println("locker:") print_stack (l)
                println("unlocker:") print_stack (u)

                println(@hist_log (lockhistory[l,u]))

                if (@max (lockhistory[l,u]) > 100)
                   println("--- holy cow, that can take a long time ---")
        }
        exit()
}



% sudo stap bkl.stp
[...]
locker:
 0xffffffff812bdcec : lock_kernel+0x1/0x37 [kernel]
 0xffffffff812bf12b : kretprobe_trampoline_holder+0x4/0x50 [kernel]
 0xffffffff811b067b : write_chan+0x273/0x338 [kernel]
 0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel]
 0xffffffff811ade5f : tty_write+0x184/0x213 [kernel]
 0xffffffff811b0408 : write_chan+0x0/0x338 [kernel]
 0x00000ffffffff810
unlocker:
 0xffffffff812bdca9 : unlock_kernel+0x1/0x31 [kernel]
 0xffffffff811b064e : write_chan+0x246/0x338 [kernel]
 0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel]
 0xffffffff811ade5f : tty_write+0x184/0x213 [kernel]
 0xffffffff811b0408 : write_chan+0x0/0x338 [kernel]
 0xffffffff810b6f89 : vfs_write+0xae/0x157 [kernel]
 0x00000fffffffff7f
value |-------------------------------------------------- count
    0 |                                                     3
    1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    570
    2 |@@@@@@@@@@@@@                                      159
    4 |                                                     9
    8 |@                                                   16
   16 |                                                     3
   32 |@@                                                  35
   64 |                                                     5
  128 |                                                     0
  256 |                                                     0

locker:
 0xffffffff812bdcec : lock_kernel+0x1/0x37 [kernel]
 0xffffffff812bf12b : kretprobe_trampoline_holder+0x4/0x50 [kernel]
 0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel]
 0xffffffff811ade5f : tty_write+0x184/0x213 [kernel]
 0xffffffff811b0408 : write_chan+0x0/0x338 [kernel]
 0xffffffff810b6f89 : vfs_write+0xae/0x157 [kernel]
 0x00000fffffffff7f
unlocker:
 0xffffffff812bdca9 : unlock_kernel+0x1/0x31 [kernel]
 0xffffffff811b064e : write_chan+0x246/0x338 [kernel]
 0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel]
 0xffffffff811ade5f : tty_write+0x184/0x213 [kernel]
 0xffffffff811b0408 : write_chan+0x0/0x338 [kernel]
 0xffffffff810b6f89 : vfs_write+0xae/0x157 [kernel]
 0x00000fffffffff7f
value |-------------------------------------------------- count
    0 |                                                     0
    1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      454
    2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  497
    4 |@@                                                  21
    8 |@                                                   15
   16 |                                                     1
   32 |@@@                                                 33
   64 |                                                     2
  128 |                                                     0
  256 |                                                     0



NB: Observed lock times in the 1-2 us range indicate no contention, as
that's on the order of magnitude of the (un)lock_kernel kprobe
overheads.


- FChE

Re: [PATCH 5/5] tracing/ftrace: Introduce the big kernel lock tracer

[Frédéric Weisbecker]

2008/10/23 Frank Ch. Eigler <fche@redhat.com>:
> For comparison, this is how this sort of analysis may be done with
> systemtap, just for fun collecting locking latency on a
> per-locker/unlocker (stack traceback) basis.  We don't have the stack
> traceback extended right into userspace yet, but will before too long.
>
>
> % cat bkl.stp
> probe kernel.function("lock_kernel") {
>        locker=backtrace()
>        locktime=gettimeofday_us()
> }
>
> probe kernel.function("lock_kernel").return {
>        unlocktime=gettimeofday_us()
>        delay = unlocktime-locktime
>        lockhistory[locker,unlocker] <<< delay
> }
>
> probe kernel.function("unlock_kernel") {
>        unlocker=backtrace()
> }
>
> global locker, unlocker, locktime, lockhistory
>
> probe end,timer.s(30) { // interrupt any time; automatic ending in 30s
>        foreach ([l,u] in lockhistory+) { // in increasing order of @count()
>
>                println("locker:") print_stack (l)
>                println("unlocker:") print_stack (u)
>
>                println(@hist_log (lockhistory[l,u]))
>
>                if (@max (lockhistory[l,u]) > 100)
>                   println("--- holy cow, that can take a long time ---")
>        }
>        exit()
> }
>
>
>
> % sudo stap bkl.stp
> [...]
> locker:
>  0xffffffff812bdcec : lock_kernel+0x1/0x37 [kernel]
>  0xffffffff812bf12b : kretprobe_trampoline_holder+0x4/0x50 [kernel]
>  0xffffffff811b067b : write_chan+0x273/0x338 [kernel]
>  0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel]
>  0xffffffff811ade5f : tty_write+0x184/0x213 [kernel]
>  0xffffffff811b0408 : write_chan+0x0/0x338 [kernel]
>  0x00000ffffffff810
> unlocker:
>  0xffffffff812bdca9 : unlock_kernel+0x1/0x31 [kernel]
>  0xffffffff811b064e : write_chan+0x246/0x338 [kernel]
>  0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel]
>  0xffffffff811ade5f : tty_write+0x184/0x213 [kernel]
>  0xffffffff811b0408 : write_chan+0x0/0x338 [kernel]
>  0xffffffff810b6f89 : vfs_write+0xae/0x157 [kernel]
>  0x00000fffffffff7f
> value |-------------------------------------------------- count
>    0 |                                                     3
>    1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    570
>    2 |@@@@@@@@@@@@@                                      159
>    4 |                                                     9
>    8 |@                                                   16
>   16 |                                                     3
>   32 |@@                                                  35
>   64 |                                                     5
>  128 |                                                     0
>  256 |                                                     0
>
> locker:
>  0xffffffff812bdcec : lock_kernel+0x1/0x37 [kernel]
>  0xffffffff812bf12b : kretprobe_trampoline_holder+0x4/0x50 [kernel]
>  0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel]
>  0xffffffff811ade5f : tty_write+0x184/0x213 [kernel]
>  0xffffffff811b0408 : write_chan+0x0/0x338 [kernel]
>  0xffffffff810b6f89 : vfs_write+0xae/0x157 [kernel]
>  0x00000fffffffff7f
> unlocker:
>  0xffffffff812bdca9 : unlock_kernel+0x1/0x31 [kernel]
>  0xffffffff811b064e : write_chan+0x246/0x338 [kernel]
>  0xffffffff810305e0 : default_wake_function+0x0/0xf [kernel]
>  0xffffffff811ade5f : tty_write+0x184/0x213 [kernel]
>  0xffffffff811b0408 : write_chan+0x0/0x338 [kernel]
>  0xffffffff810b6f89 : vfs_write+0xae/0x157 [kernel]
>  0x00000fffffffff7f
> value |-------------------------------------------------- count
>    0 |                                                     0
>    1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      454
>    2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  497
>    4 |@@                                                  21
>    8 |@                                                   15
>   16 |                                                     1
>   32 |@@@                                                 33
>   64 |                                                     2
>  128 |                                                     0
>  256 |                                                     0
>
>
>
> NB: Observed lock times in the 1-2 us range indicate no contention, as
> that's on the order of magnitude of the (un)lock_kernel kprobe
> overheads.

That's a great and powerful tool.

But just one sorrow:
I just think that's a pity that we have to use/learn a new scripting
language to use it.
I would rather prefer to use an API that provides functions/objects
for most common scripting languages.

Re: [PATCH 5/5] tracing/ftrace: Introduce the big kernel lock tracer

[Frank Ch. Eigler]

Hi -

On Fri, Oct 24, 2008 at 03:43:49PM +0200, Frédéric Weisbecker wrote:

> > [...]  For comparison, this is how this sort of analysis may be
> > done with systemtap [...]

> That's a great and powerful tool.
> 
> But just one sorrow:
> I just think that's a pity that we have to use/learn a new scripting
> language to use it.

I understand.

> I would rather prefer to use an API that provides functions/objects
> for most common scripting languages.

That is an interesting idea.  One possible problem is that the final
complete script "program" needs to be translated to something that can
run quickly and safely inside the kernel.  Full python or perl runtime
+ libraries would have been almost certainly unbearable.

- FChE

Re: [PATCH 5/5] tracing/ftrace: Introduce the big kernel lock tracer

[Steven Rostedt]

On Fri, 24 Oct 2008, Frank Ch. Eigler wrote:

> Hi -
> 
> On Fri, Oct 24, 2008 at 03:43:49PM +0200, Fr?d?ric Weisbecker wrote:
> 
> > > [...]  For comparison, this is how this sort of analysis may be
> > > done with systemtap [...]
> 
> > That's a great and powerful tool.
> > 
> > But just one sorrow:
> > I just think that's a pity that we have to use/learn a new scripting
> > language to use it.
> 
> I understand.
> 
> > I would rather prefer to use an API that provides functions/objects
> > for most common scripting languages.
> 
> That is an interesting idea.  One possible problem is that the final
> complete script "program" needs to be translated to something that can
> run quickly and safely inside the kernel.  Full python or perl runtime
> + libraries would have been almost certainly unbearable.

Why can't the userspace application convert the script to something easy 
that the kernel can handle?  But have the user application interface be 
very simple, and perhaps even use perl or python.

-- Steve

Re: [PATCH 5/5] tracing/ftrace: Introduce the big kernel lock tracer

[Frank Ch. Eigler]

Hi -

On Fri, Oct 24, 2008 at 10:47:36AM -0400, Steven Rostedt wrote:
> [...]
> > > I would rather prefer to use an API that provides functions/objects
> > > for most common scripting languages.
> > 
> > That is an interesting idea.  One possible problem is that the final
> > complete script "program" needs to be translated to something that can
> > run quickly and safely inside the kernel.  Full python or perl runtime
> > + libraries would have been almost certainly unbearable.
>
> Why can't the userspace application convert the script to something
> easy that the kernel can handle?

That's what we do with the systemtap script, where kernel "handling"
consists of "running the machine code".

> But have the user application interface be very simple, and perhaps
> even use perl or python.

perl and python are pretty big procedural languages, and are not
easily compiled down to compact & quickly executed machine code.  (I
take it no one is suggesting including a perl or python VM in the
kernel.)  Plus, debugger-flavoured event-handling programming style
would not look nearly as compact in perl/python as in systemtap, which
is small and domain-specific.

- FChE

Re: [PATCH 5/5] tracing/ftrace: Introduce the big kernel lock tracer

[Frédéric Weisbecker]

2008/10/24 Frank Ch. Eigler <fche@redhat.com>:
> That's what we do with the systemtap script, where kernel "handling"
> consists of "running the machine code".
>
>> But have the user application interface be very simple, and perhaps
>> even use perl or python.
>
> perl and python are pretty big procedural languages, and are not
> easily compiled down to compact & quickly executed machine code.  (I
> take it no one is suggesting including a perl or python VM in the
> kernel.)  Plus, debugger-flavoured event-handling programming style
> would not look nearly as compact in perl/python as in systemtap, which
> is small and domain-specific.
>
> - FChE
>

Actually what I thought is a style like this (Python like):

probe = Systemtap.probeFunc("lock_kernel")
probe.captureUtime("utime"))
probe.captureBacktrace("trace")
probe.trace()

For an obvious set of batch work like that, that could be possible,
perhaps even easy
to implement an Api...
When the object calls trace(), the userspace Systemtap analyse the list
of work to do and then translate into commands in kernel space.

And the script could wait for events and then do its own processing
with the captured events
(do some operations on delays, on output....).

for event in probe.getEvent(): #blocking
    print event["utime"]
    trace = event["trace"] #Systemtap.trace object with specific
fields and a default string repr
    print trace

It would be interpreted by Python itself, and you just have to capture
commands and works
sent through Api. Then, when the kernel has something to give, you
just have to place it in the
appripriate object and transmit it to the script which is waiting.
Processing and output with the data are done by the python script.
So actually, the python script only needs to ask you what data to
capture. It's its own responsability to
do wathever it wants with.

What do you think?

Re: [PATCH 5/5] tracing/ftrace: Introduce the big kernel lock tracer

[Frank Ch. Eigler]

Hi -

On Fri, Oct 24, 2008 at 05:26:53PM +0200, Frédéric Weisbecker wrote:
> [...]
> Actually what I thought is a style like this (Python like):
> 
> probe = Systemtap.probeFunc("lock_kernel")
> probe.captureUtime("utime"))
> probe.captureBacktrace("trace")
> probe.trace()
> 
> For an obvious set of batch work like that, that could be possible,
> perhaps even easy to implement an Api...
> When the object calls trace(), the userspace Systemtap analyse the list
> of work to do and then translate into commands in kernel space.

There comes a point not too far beyond this example where one may want
to capture functions of values; filter; perform loops/conditionals;
refer to variables/arrays.  Coding that logic this way would be so
clumsy as to take away any charm of working in python.


> And the script could wait for events and then do its own processing
> with the captured events (do some operations on delays, on output....).
> 
> for event in probe.getEvent(): #blocking
>     print event["utime"]
>     trace = event["trace"] #Systemtap.trace object with specific
> fields and a default string repr
>     print trace
> 
> It would be interpreted by Python itself [...]

This is too gets impractical.  If the only event handler code is
general python, it can't practically be executed within the kernel.
So we're then talking about a python script consuming trace data
streamed in.  We lose:
- capability to take immediate action upon event occurrence
- any claim to good performance (~microsecond event handling)
- the natural coupling between events and their handlers
- the ability to statically analyze the entire instrumentation,
  to optimize locking, data encoding


Now, one may imagine using this sort of thing as a *wrapper* around
plain systemtap: where the python libraries generate stylized
systemtap code that emits data in a form that the later "getEvent"
routine can decode again and act upon.

Several people have written shell, perl, even awk scripts scripts to
generate systemtap code for particular special purposes.  So one can
hide the script language as an implementation detail of a higher level
tool.  It's not a substitute though.


- FChE

Re: [PATCH 5/5] tracing/ftrace: Introduce the big kernel lock tracer

[Tom Zanussi]

Hi,

This is a great idea.  Some thoughts on how it could work below...

On Fri, 2008-10-24 at 17:26 +0200, Frédéric Weisbecker wrote: 
> 2008/10/24 Frank Ch. Eigler <fche@redhat.com>:
> > That's what we do with the systemtap script, where kernel "handling"
> > consists of "running the machine code".
> >
> >> But have the user application interface be very simple, and perhaps
> >> even use perl or python.
> >
> > perl and python are pretty big procedural languages, and are not
> > easily compiled down to compact & quickly executed machine code. (I
> > take it no one is suggesting including a perl or python VM in the
> > kernel.) Plus, debugger-flavoured event-handling programming style
> > would not look nearly as compact in perl/python as in systemtap,
> which
> > is small and domain-specific.
> >
> > - FChE
> >
> 
> Actually what I thought is a style like this (Python like):
> 
> probe = Systemtap.probeFunc("lock_kernel")
> probe.captureUtime("utime"))
> probe.captureBacktrace("trace")
> probe.trace()
> 
> For an obvious set of batch work like that, that could be possible,
> perhaps even easy
> to implement an Api...
> When the object calls trace(), the userspace Systemtap analyse the
> list
> of work to do and then translate into commands in kernel space.
> 

When you say 'translate into commands in kernel space', I'm assuming in
the simplest case that you're thinking of the trace() method on your
Python probe object as generating systemtap probe code which in this
case would insert a probe on "lock_kernel" and collect the specific data
you named in the captureXXX methods.  If so, then the generated
systemtap code might look something like this (my systemtap coding is a
bit rusty and I don't know Python at all, so, please excuse any coding
problems - think of it as pseudo-code):

global ID_LOCK_KERNEL = 1;

/* systemtap code - in turn generates kernel code/module */
probe kernel.function("lock_kernel")
{
        /* log captureXXX fields using systemtap binary printf */
        printf("%b2%b4%s", ID_LOCK_KERNEL, utime, backtrace());
}

Once the trace method generates the systemtap probe code, it would then
construct the appropriate stap command line, exec it (which compiles the
generated probe code, inserts the module, arms the probes, etc) and from
then on sits around waiting for output from the probe...

> And the script could wait for events and then do its own processing
> with the captured events
> (do some operations on delays, on output....).
> 
> for event in probe.getEvent(): #blocking
> print event["utime"]
> trace = event["trace"] #Systemtap.trace object with specific
> fields and a default string repr
> print trace
> 
> It would be interpreted by Python itself, and you just have to capture
> commands and works
> sent through Api. Then, when the kernel has something to give, you
> just have to place it in the
> appripriate object and transmit it to the script which is waiting.
> Processing and output with the data are done by the python script.
> So actually, the python script only needs to ask you what data to
> capture. It's its own responsability to
> do wathever it wants with.

...as it receives the probe output, it would then extract the individual
events from the stream and dispatch them to the event-handling Python
code, which would be able to do whatever it wants to with...

There are at least two different ways I can think of to do this part.

The most straightforward would be to do it all in pure Python in the
script receiving the probe output.  Since I don't know Python, I'll use
pseudo-Perl, but the idea would be the same for Python:

open EVENT_STREAM, "stap -g lock-kernel-probe.stp"

while (<EVENT_STREAM>) {
  /* userspace Perl code: get and dispatch the next event id */
  $id = unpack("C"); /* Perl function for pulling apart C structs */

  /* dispatch to matching on_xxx 'handler' function */
  switch ($id) {
          case ID_LOCK_KERNEL:
                  /* unpack event, call handler using param array */
                  on_lock_kernel(unpack("XCLZ"));
                  break;
          default:
                  break;
  }
}

The Perl script code above continually grabs the next event on the
output stream, uses the first byte to figure out which event it
corresponds to and once it knows that, grabs the rest of the event data
and finally dispatches it to the 'handler' function for that event:

/* userspace Perl code: lock_kernel event 'handler' */
sub on_lock_kernel
{
        /* get the params */
        my ($id, $utime, $stacktrace) = @_;
        /* add to hash tracking times we've seen this stacktrace */
        $stacktraces{$stacktrace}++;
}

The handler code gets the data as usual via the params and does what it
wants with it; in this case it just uses the stack trace as a hash key
to keep a running count of the number of times that particular path was
hit.

Finally, at the end of the trace, a special end-of-trace handler gets
called, which can be used e.g. to dump the results out: 

/* userspace Perl code: at the end of the trace, dump what we've got */
sub on_end_trace_session
{
        while (($stacktrace, $count) each %stacktraces) {
                print "Stacktrace: $stacktrace\n";
                print "happened $stacktraces{$stacktrace} times\n";
        }
}

Another, presumably more efficient way to do the same thing, would be to
'embed' and instantiate an instance of the interpreter in the daemon
code.  The same (in this case) end-use Perl on_XXX event handlers would
be called, but the unpacking code and dispatch loop would be done in C
code as part of the daemon.  There, the fields of each event would be
translated into a form understandable by the interpreter and the handler
in the embedded interpreter invoked for each event:

/* userspace C code: get and dispatch the next event id */
unsigned char id = next_event_id(event_stream);

/* dispatch to matching on_xxx 'handler' function in Perl interpreter*/
switch (id) {
        case ID_LOCK_KERNEL:
                /* unpack event, call handler using param array */
                unsigned long = next_event_long(event_stream);
                char *string = next_event_string(event_stream);
                perl_invoke_on_lock_kernel(utime, stacktrace);
                break;
        default:
                break;
}

/* userspace C code: embedded Perl magic for invoking a Perl function */
void perl_invoke_on_lock_kernel(unsigned long utime, char *stacktrace)
{
        CALLBACK_SETUP(on_lock_kernel);
        XPUSHs(sv_2mortal(newSViv(utime)));
        XPUSHs(sv_2mortal(newSVpvn(stacktrace, strlen(stacktrace))));
        CALLBACK_CALL_AND_CLEANUP(on_lock_kernel);
}

The above dispatch loop, unpacking, etc is pretty much the same as in
the 'pure Perl' version, but done in C, and with the exception that it
does some interpreter-specific magic to invoke the interpreter methods,
which are exactly the same as in the 'pure' version.

I actually did this for every single event in the old LTT (not the
language binding, just the dispatching-to-to script-level handlers
part), so I know it works in practice and in fact it worked very well -
it was able to handle a pretty heavy trace stream while doing all the
nice Perl hashing/summing/etc in the event handlers it needed to do in
order to produce interesting and non-trivial results; IIRC it
comfortably handled full tracing (all events) during a kernel compile:

http://lkml.org/lkml/2004/9/1/197

And, not to knock the systemtap language, which is a fine and capable
language, but even the simple scripts I wrote for that demo did things
that exceeded the capabilities of the systemtap language (and the dtrace
language as well, I should add).

> What do you think?

I think what you want to do is quite doable, however you decide to do
it.  I know Python too has an API for embedding interpreters and
invoking script methods, as most non-trivial scripting languages do.  My
guess is that if you took the embedded interpreter approach for Python,
with a little generalization you could have a common layer to the
implementation that other languages could easily plug into.

Also, once you had the basic stuff working, you could extend it and in
the process make more use of the filtering and other capabilities
systemtap offers i.e. you needn't be limited to just using systemtap to
'scrape' data and do all the processing in the userspace Python script.

One example would again be stacktraces, which because of their size, are
things that you probably wouldn't want to send to userspace at a very
high frequency.  Here's an example of a combination systemtap kernel
script/Perl userspace script that continuously streams and converts
systemtap hashes into Perl hashes (because sytemtap kernel resources are
necessarily limited whereas userspace Perl interpreter resources
aren't):

http://sourceware.org/ml/systemtap/2005-q3/msg00550.html

It's a good example of a case where doing filtering in the kernel makes
a lot of sense.  With the hybrid systemtap/Perl/Python approach, you
make use of the strengths of systemtap while at the same time retaining
the full power of your language of choice. 

Of course, one of the challenges in using the more advanced features of
systemtap would be in making those capabilities available as natural
extensions to the supported scripting language(s).  But even without
them, I think the basic mode would be an extremely useful and powerful
complement to systemtap. 

Tom