From mboxrd@z Thu Jan  1 00:00:00 1970
From: mathieu.desnoyers@efficios.com (Mathieu Desnoyers)
Date: Mon, 15 Nov 2010 11:07:45 -0500
Subject: [ltt-dev] [ANNOUNCE] New tools: lttngtrace and lttngreport
In-Reply-To: <20101115134243.GA2772@Krystal>
References: <20101115134243.GA2772@Krystal>
Message-ID: <20101115160745.GA7203@Krystal>

* Mathieu Desnoyers (mathieu.desnoyers at efficios.com) wrote:
> 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.

Hi again,

I just enhanced the wakeup dependency chain output to make it more
understandable by humans. It's astonishing what we can do with a bit of ASCII
art. For instance, here I am showing piece of firefox start trace:

        --> Blocked in RUNNING, SYSCALL 142 [sys_select+0x0/0xc0], ([...], dur: 0.029567)
        |    --> Blocked in RUNNING, SYSCALL 168 [sys_poll+0x0/0xc0], ([...], dur: 1.187935)
        |    --- Woken up by an IRQ: IRQ 0 [timer]
        --- Woken up in context of 7401 [gnome-power-man] in high-level state RUNNING

As you see, firefox blocked for 29.5 microseconds on select() waiting for a file
descriptor, the wake up came from "gnome-power-manager" after the poll() timed
out (1 second timeout). (This specific scenario cannot be reproduced at every
firefox run, but it is still a good example of how these spurious delays can be
identified with the tool.)

Thanks,

Mathieu

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