[ANNOUNCE] New tools: lttngtrace and lttngreport

[Mathieu Desnoyers <mathieu.desnoyers@efficios.com>]

Hi everyone,

Recently, Linus came up with a request: a "super-strace" based on kernel
tracing. So I just came up with two bash scripts that perform exactly this within
LTTng: lttngtrace starts tracing, runs a program, stops tracing. lttngreport
generates a wakeup dependency report. I'm appending the script below (depends on
LTTng kernel tree, LTTng modules package, ltt-control and lttv).

It will report which interrupt/softirq and wakeup dependency chain caused each
wakeup, along with the duration within each step of the wakeup chain. This
includes I/O activity, traps, and syscalls.

Usage, e.g. to trace a git clone (must be run as root):

# lttngtrace git clone git://git.lttng.org/lttv.git
[...]

% lttngreport
[...]
Woken up in context of 29856 [/usr/lib/git-core/git] in high-level state RUNNING
Blocked in RUNNING, SYSCALL 7 [sys_waitpid+0x0/0x30], (times: 139642.854813709-139642.855068608, dur: 0.000255)
Woken up in context of 29856 [/usr/lib/git-core/git] in high-level state RUNNING
Blocked in RUNNING, SYSCALL 118 [sys_fsync+0x0/0x10], (times: 139642.855714820-139642.855795631, dur: 0.000081)
Woken up by a SoftIRQ: SoftIRQ 4 [blk_done_softirq+0x0/0x70]
Blocked in RUNNING, SYSCALL 118 [sys_fsync+0x0/0x10], (times: 139642.855870453-139642.858538485, dur: 0.002668)
         Blocked in UNKNOWN, (times: 139642.855869565-139642.858434668, dur: 0.002565)
         Woken up by a SoftIRQ: SoftIRQ 4 [blk_done_softirq+0x0/0x70]
         Blocked in UNKNOWN, (times: 139642.858483534-139642.858528693, dur: 0.000045)
         Woken up by a SoftIRQ: SoftIRQ 4 [blk_done_softirq+0x0/0x70]
Woken up in context of 1140 [kjournald]UNKNOWN,  in high-level state UNKNOWN
Blocked in RUNNING, SYSCALL 168 [sys_poll+0x0/0xc0], (times: 139642.859478216-139642.860636322, dur: 0.001158)
Woken up by a SoftIRQ: SoftIRQ 3 [net_rx_action+0x0/0x1e0]
Blocked in RUNNING, SYSCALL 38 [sys_rename+0x0/0x30], (times: 139642.861159211-139642.861240877, dur: 0.000082)
Woken up by a SoftIRQ: SoftIRQ 4 [blk_done_softirq+0x0/0x70]

I'll be happy to tweak the report as I receive feedback.

(bash scripts below, depends on current lttv git tree)

Thanks,

Mathieu

-------
lttngtrace:

#!/bin/sh

rm -fr /tmp/autotrace1
ltt-armall

lttctl -C -w /tmp/autotrace1 autotrace1

${*} &
CHILDPID=$!
wait

lttctl -D autotrace1
ltt-disarmall

echo ${CHILDPID} > /tmp/autotrace1-pid

------
lttngreport:

#!/bin/sh

CHILDPID=$(cat /tmp/autotrace1-pid)

lttv -m depanalysis -t /tmp/autotrace1 --dep-pid ${CHILDPID}


-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com