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

From: Frédéric Weisbecker
Date: Fri Oct 24 2008 - 09:44:07 EST


2008/10/23 Frank Ch. Eigler <fche@xxxxxxxxxx>:
> 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.
--
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/