The Linux Trace Toolkit

This is the most interesting part about LTT and what differentiates it from other tools. Even though the current example is rather simplistic, more elaborate traces can be generated and analyzed just as easily. To view the trace in the graphical front end, simply type:

traceview out140

The traceview script accepts one argument: the base name of the generated trace. It then executes the trace toolkit front end, passing it the out140.trace and out140.proc files. Note that the front end can be invoked manually and can be used as a command-line tool as well. In the latter case, it can be used to dump the contents of trace in a human-readable format or perform a detailed trace analysis. The complete options are described in the documentation included with LTT.

A sample display of the front end can be seen in Figure 1. As usual, there is a menu, a toolbar and the data. To present the data, the tool uses three thumbnails. The first, Event Graph, presents the events in a graphical way. On the left, a list of all processes that existed during the trace is presented. On the right, a scrollable graph displays the transitions that marked the time frame being displayed. A vertical transition means the flow of control has been passed to another entity. The color of the vertical line used for the transitions indicates the type of event that caused the transition. Blue is for a system call, grey for a trap and white for an interrupt. Horizontal lines indicate the time spent executing code belongs to the entity in the process list at the same height. A green line is for application code and an orange line is for kernel code.

Figure 1. LTT Front End

In Figure 1, we can see that sh was running and a page fault occurred. Control was transfered to the kernel, which did some operations and then gave control back to sh. The latter executed for a while, then did a wait4 system call. This, in turn, gave control back to the kernel. After a couple of operations, the kernel decided to do a task switch and handed control to process 152, bzip2. While bzip2 was running, another trap occurred. Toward the end of the trace, we can see bzip2 made a system call to getpid, and on returning, continued executing.

Figure 2 presents a more interesting case. For illustration purposes, the trace portion was zoomed out; some icons overlap, but the meaning is fairly straightforward. Here, bzip2 tries to read something, but the kernel doesn't find it. bzip2 starts waiting for I/O (input/output) and the kernel schedules the idle task. Two milliseconds later, the hard disk sends an interrupt to signal that it finished reading (that's the icon with a chip and an exclamation mark with a 14 beside it, 14 being the IDE disk IRQ). bzip2 is then rescheduled, stops waiting for I/O and returns to its normal execution. Here, we can see exactly how much time bzip2 spent waiting for I/O and the exact chronology of events that led to it losing CPU control and regaining it. When trying to comprehend complex interactions between tasks, this type of information can make all the difference.

Figure 2. Event Graph

Giving a different perspective, the second thumbnail, Process Analysis, provides us with an in-depth analysis of each process that existed during the trace and a global analysis of the system. Figure 3 presents a sample of this analysis. On the left, the process tree is presented. At the top of the tree lies the idle task (PID 0) which is presented as being The All Mighty. Since the idle task never does anything worth tracing, it is used to present data about the whole system: trace start time, trace end time, duration, time spent idle (idle was scheduled as running). Then the number of occurrences of key events is presented. Notice some events given here can't be accounted for by using the information in /proc.

Figure 3. Process Analysis

Listing 1

When selecting dir and bzip2 processes, the information in Listing 1 is displayed. Notice the difference in percentages between the time running (time scheduled by the kernel as having control over the CPU) and the time spent actually executing code belonging to the application. In bzip2's case, the gap is very small, which accurately describes bzip2's behavior as CPU-intensive; whereas in dir's case, less than half of the time it was scheduled was spent executing its own code, the rest being spent in kernel routines.

Note also the differences between the time spent waiting for I/O and the time running. dir spent more time waiting for I/O than it spent executing. bzip2, on the other hand, spent little time waiting for I/O compared to the time it spent in running state. This information wasn't collected using sampling on the system clock, as is done currently for the information available through /proc. This information is calculated using the trace information and is therefore the exact information regarding the observed task.

Last but not least, the third thumbnail presents the raw trace. Figure 4 presents a portion of a raw trace. The events are presented in chronological order of occurrence. For each event, the following information is given: the CPU-ID of the processor on which it occurred, the event type, the exact time of occurrence (down to the microsecond), the PID of the task to which it belongs, the size of the entry in the kernel module that was taken in order to record the event in full and the description of the event. Notice how the address from which a system call was made is displayed. This could eventually be used to correlate with data recorded from within the application or simply to know which part of the code made the call. Unlike other tracing methods such as ptrace, there is no effect on the application's behavior, except the minimal event-data collection delays.

Figure 4. Portion of Raw Trace