Visiting Event Tracing for Windows

In previous posts, we discussed Linux kernel tracing with LTTng. On the Microsoft side, Event Tracing for Windows allows to gather a kernel trace and user space trace. It's advertised as low-impact, lock-less, per-cpu buffers tracer, with live mode and circular buffers option. Quite interesting.
Here is a quick introduction to how to gather a simple trace on Windows 7 Professional and the different analysis we can get.

Installation

Obviously, you will need a Windows 7 Professional host. I installed it in a Linux KVM virtual machine, with 20GB of storage and with two CPUs emulated, with all default options.
First, .NET framework 4 has to be installed, required to install tracing tools bundled with Windows SDK.
In summary, you need to install:

• dotNetFx40_Full_x86_x64
• winsdk_web

It will install required tools for tracing: xperf, xperfview, tracelog and tracerpt.

Get a trace

To start tracing, open a console in administration mode, as shown in the following screen shot.

We create a trace directory for our experiments, and start and stop a simple trace with tracelog, as shown in the following screen shot. While tracing, you can start programs to create some activity on the system. I started IE and did some random browsing.

The trace file output is set with "-f" option. If a lot of events occurs, some events can be lost. If such a thing occur, increase the buffers size with "-b" option. Other options are there for some extra trace events, refer to help for more information. To give an idea of the disk requirement, I got a trace of about 20MB for a minute of tracing under light load. The trace file can hence become very big.

If the user doesn't have enough privileges for tracing, the following error message will be raised. Make sure the console is launched as administrator.

C:\trace>tracelog -f kernel.etl -start
Setting log file to: C:\trace\kernel.etl
Could not start logger: NT Kernel Logger
Operation Status: 5L
Access is denied.



Analyze the trace

Launch xperfview to start the Windows Performance Analyzer. Then, load the trace kernel.etl obtained previously. Here is what it looks like.

Disk access graph and CPU usage according to time and process in xperfview.

Process life graph and page faults by process according to time in xperfview.

Offset of disk access to detect system-wide bad seek behavior.

Summary of events count obtained from tracerpt

What I like about xperf is the ability to isolate resource usage per process. Also, zooming in a trace is intuitive by selecting with the mouse an interval that seems interesting. Trace events are completely abstracted as chart and statistics. There views are appropriate for understanding overall system performance. Also, when executable symbols are loaded, the call trace performance is available, which may be very handy for the software optimization. 
The tracerpt utility outputs reports from a trace file, one is the count of all events and the report in HTML gives the statistics for the whole trace by subsystem. Here is an example of report.html generated with tracerpt.

Tracing a linux cluster

Gather traces from multiple machines and then showing them all at once is a real challenge, because each computer has it's own independent clock. It means that two events occurring at the same time on two computers have a low probability to have the same time stamp in the trace.

Linux Trace Toolkit have a synchronization feature to adjust trace time stamps to a reference trace. It works by matching sent and received network packets found in traces. Two parameters are computed: an offset, but also a drift, that is the rate of clock change.

To experiment it, I did a virtual Ubuntu cluster of 10 nodes installed with LTTng. Virtual machines are sending each other TCP packets with the small utility pingpong while tracing is enabled. All traces are then sync to the host for analysis. Here are the results:

$ lttv -m sync_chain_batch --sync --sync-stats -t trace1 -t trace2 [...]
[...]
Resulting synchronization factors:
 trace 0 drift= 1 offset= 6.80407e+09 (2.551684) start time= 2433.182802117
 trace 1 drift= 1 offset= 4.12691e+09 (1.547687) start time= 2433.254700670
 trace 2 drift= 0.999999 offset= 0 (0.000000) start time= 2433.229372444
 trace 3 drift= 1 offset= 1.53079e+09 (0.574083) start time= 2433.366687088
 trace 4 drift= 1 offset= 2.31812e+10 (8.693471) start time= 2433.217954184
 trace 5 drift= 1 offset= 1.48957e+10 (5.586227) start time= 2433.280525047
 trace 6 drift= 1 offset= 1.76688e+10 (6.626211) start time= 2433.291125350
 trace 7 drift= 1 offset= 2.0463e+10 (7.674116) start time= 2433.325424020
 trace 8 drift= 0.999999 offset= 1.2206e+10 (4.577534) start time= 2433.204361289
 trace 9 drift= 1 offset= 9.55947e+09 (3.585022) start time= 2433.293578996
[...]

The trace 2 has been selected as the reference trace. We see inside parenthesis the offset between the current trace and the reference trace. We see a delay between each trace that match the delay between virtual machines startup. When loading these traces into lttv with --sync option, all traces events align perfectly, which is not the case without the sync option.

If you want to know more about trace synchronization, I recommend the paper Accurate Offline Synchronization of Distributed Traces Using Kernel-Level Events from Benjamin Poirier.

One simple note if you want to do this analysis, you need extended network trace events. To enable them, arm ltt with

$ sudo ltt-armall -n

I found it really interesting, because it allows to see cluster-wide system state.

CPU history from kernel trace

Everybody is familiar with CPU history usage, for example with GNOME monitor. We see the average usage in time.

The GNOME monitor poll /proc/stats at regular interval to compute average usage. This file is updated by the kernel. The values comes from sampling that the kernel does for accounting various process.

How could we compute the CPU usage history from the actual kernel trace? We only have to look at sched_schedule events. The event inform us that in a certain point in time, the kernel switched the task on a given CPU. If the new task has PID zero, we know that's the idle thread from the kernel. By splitting running and idle time in fixed intervals, we can compute CPU average usage.

I show one small examples done on my computer that is dual core. First, we see the execution of three cpuburn process started with one second of delay. We can see the result in the control flow viewer in LTTV, and the resulting CPU usage view.

We see a peek at the beginning of the trace. This is likely to be related to the metadata flushing when a trace is started. The two steps after are related to each cpuburn process, and we see that when the third process is started, the CPU usage stays at 100%.

For testing, I added scripts to generate those traces automatically on your computer. It's written in Java, and you will need some extra packages to run it, see the README file. Get the code on github:

https://github.com/giraldeau/flightbox

Happy hacking!

Introduction to Linux Tracing Toolkit

The Linux Tracing Toolkit next generation (LTTng) is absolutely amazing. In this introduction, we will look at how to interpret the kernel trace of a small program by comparing it to strace. If you want to install components and get a trace on your own machine, you can get packages for the patched kernel and other tools for Ubuntu Maverick in LTTng's PPA on Launchpad. You will also need build-essential to compile the small C executable, strace and hexdump.

Here is the small program. It opens a file and write a integer into it. Then, it adds number in a for loop.

#include <stdio.h>
#define INT_MAX 2147483647
int main(volatile int argc, char **argv) {
    int i = 3;
    FILE *fd = fopen("test.out", "w");
    fwrite(&i, sizeof(int), 1, fd);
    fclose(fd);
    volatile long a;
    int x;
    for (x = 0; x<INT_MAX; x++) {
        a++;
    }
    return 0;
}

Compile it, test it and run it under strace:

$ gcc -o usecase usecase.c
$ ./usecase
$ strace -o usecase.strace ./usecase

Ok. Now, let's run the program under tracing, but before, we have to enable all trace points in the kernel.

$ sudo ltt-armall

To get a tight window around the command, I'm using the small script trace-cmd.sh (see at the end of the post). The script simply starts tracing, run the program and stop the trace. Invoke it like this (don't forget to set the script executable):

./trace-cmd.sh ./usecase

Now, we are ready to launch lttv-gui, which is the utility to look at the trace. To load a trace, select File->Add trace, then select the "trace-cmd" directory created in the same directory as the trace-cmd.sh script. Then, scroll down to the "./usecase" process in the control flow viewer, which is in the middle of the window. Each trace events are displayed under the graph. I will present three phase of the process. First, the creation and file access, then computation phase and the process exit. Trace is rotated to make it more readable. Events name and comments are embedded in the graph. strace events are in red, while related code is in blue.

In addition to system calls, we can look at the paging of an application and see process starvation. This information is not shown by strace. Another cool side effect is that, contrary to strace, the running program can't detect it's under tracing, then we can trace viruses that otherwise quit before they can be analyzed. Tracing reports much more information about kernel internals, which helps a lot to understand what's going on. Events timestamps of the kernel trace are in nanoseconds, so the precision is really high, and since trace points are static (simple function calls compiled right into the kernel), performance impact is ridiculously low, below 3% for core trace points! I'm running LTTng in background on my system without noticeable impact, in flight recorder mode.

I will be working on advanced trace analysis for the next three years or so for my PhD. Since LTTng got all the feature I need for tracing, I will use this tools. My first goal is to create a CPU usage view. Say that something was eating your CPU a minute ago, then with kernel tracing you would be able to go in the "flight recorder" history and see what was running at that time, and understand what was going on.

You can help me in two ways. First, by submitting your ideas about cool trace analysis we could perform and/or you need. Second, you can write to Linus Torvalds and ask him to merge LTTng in mainline. LTTng is the right stuff we need for tracing and it's a bit a shame that this not merged yet while other operating systems have this since a decade.

Next post will be about TMF, an eclipse plugin for trace analysis! Stay tuned!

Script trace-cmd.sh:

#!/bin/sh

if [ -z "$@" ]; then
    echo "missing command argument"
    exit 1
fi

cmd="$@"

name="cmd"
dir="$(pwd)/trace-$name"
sudo rm -rf $dir
sudo lttctl -o channel.all.bufnum=8 -C -w $dir $name
echo "executing $cmd..."
$cmd
echo "return code: $?" 
sudo lttctl -D $name

Scary pumpkin

I left my computer for few minutes to carve the scariest pumpking for any programmer, the Big O factorial time pumpkin!

Terrifying, isn't?! Hand carved into a local organic grown pumpkin, low power lightening with LEDs, eatable after use, I'm ready for an happy hacking halloween!

Augedit: regedit for Linux

Few months ago, a prototype of GUI for Augeas was posted on the augeas-devel mailing list. I found it awesome, so I wanted to take it further. I think this is the kind of tool that can easy the configuration management on Linux, like regedit does on Windows. It's still require knowledge of what you're doing, but at least, you don't need to worry about the syntax of a particular config file! Here is a screenshot of the latest version.

On the left pane, there is a GtkTreeView, that shows the tree path and the corresponding value, if any. Then, on the right pane, there is the actual file, where the label and the value are highlighted. At this early stage, the views are read only, but the goal is to make any side editable and make the changes propagate to the other side.

Some of ideas that this kind of tool should have: basic edit operations (add, modify, move, delete, ...) searching, filtering, bookmarks, auto-completion.

If you want to try it, you will need the "myhead" branch of augeas, up to date python-augeas branch "aug_info" that adds the API function for highlighting, and the code of Augedit itself.

http://github.com/giraldeau/augeas
http://github.com/giraldeau/python-augeas
http://github.com/giraldeau/augedit

Leave your ideas about this tool in comments! ;)

Windows Phone 7 adventure

I went to Ottawa Mobile Conference, and I won as a presence prize 2 day training on Windows Phone 7 (WP7) plateform, at the Microsoft office in Ottawa. The training is provided by Colin Melia from DevTeach, which is knows the plateform very well. This was for me the occasion to get an idea of what it will look like. With the iOS, Android and RIM devices, is there a place for WP7? What it stands for? Millions of theses devices are supposed to hit the market before Thanks Giving in the US, made by Samsung, LG and Dell and others, so it has to be good.


WP7 is the Microsoft implementation of the whole mobile concept from Apple. Mobile Market is equivalent of AppStore, Zune have the same role as iTunes to sync the device and basic apps are about the same, except they are based on Microsoft technology, for example Internet Explorer replace Safari, Bing map and search replaces Google. A light version of Office and SharePoint may be free on the phone for the release. XboxLive will be the basis for all games on the device. Interesting fact, IE doesn't ship with Flash plugin. Seems that Microsoft agree with Apple on this point.

Concerning the interface, it uses the design pattern Hub and Spoke, that force the user to focus on one task at a time. A tile view of apps acts as the Hub. There are three mandatory physical button on the phone itself: back, start and search. Back goes to the previous view, start goes to the tile view and the search go to Bing. There can't multi-process running simultaneously, the same as the iPhone before multitasking. Say that you start an app, then go to the tile view and start another app, the first app instance is lost.

You can use two different libraries for an app, Silverlight for straight forward forms or XNA for games that requires more heavy video display. We saw mainly how to use Silverlight to design the UI. The application code can be written in C#, using the .NET framework classes. What is realy interesting is the clear separation between the logic and display of the application. It has been thought in such a way that the designer can work on the view independently of the programmer, that fills the view. Some preview data can be supplied to the view at design time, so the designer doesn't need the whole application to work. The UI is completely defined in XAML file in a declarative manner. A factory then read the file at runtime and create corresponding objects. .NET library provides a high level of abstraction for XML handling, HTTP and SQL queries, so in very few lines of code, a lot of things occur.

For those of you who may want to give it a try, here are some notes about installation on a MacBook Pro 1,1. The requirement and installation instructions are accurate. You need the VMX extension for virtualization to get good performances. It has to be enabled into EFI boot loader. See the Parallels knowledge base to get instructions. Microsoft supplies a small utility to check if the extension is available. But, maybe more critical is this MacBook Pro have an ATI X1600 card, and the latest (and the last) driver from AMD doesn't support WDDM 1.1, which is required for decent display performance with the phone emulator. Any computer with proper drivers for Windows 7 should do, it just means I will need a new computer to run the emulator appropriately.

In conclusion, Microsoft is jumping in the arena seriously with WP7. SDK is quite lean yet, and this is a great piece of integrated technology AFAIK. Their first step is obviously to copy recipies of competitors with their own technology. It's right, because innovation comes a lot from inspiration from others. iPhone is still the blue ocean device, and except for the Office app, there is nothing that a WP7 seems to do better, so the price point must be somewhat attractive to change the market forces. The fate of WP7 is now in the hand of customers.