Messages in this thread | | | Date | Mon, 15 Nov 2010 11:07:45 -0500 | From | Mathieu Desnoyers <> | Subject | Re: [ANNOUNCE] New tools: lttngtrace and lttngreport |
| |
* Mathieu Desnoyers (mathieu.desnoyers@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
| |