How-to setup LTTng on Fedora 19

Here is how to install lttng including kernel and userspace tracing on Fedora 19 beta.

Instructions uses sudo. To configure sudo on your fedora system, use this command as root, and replace  [username] with your username, then logout and login again:

usermod [username] -a -G wheel

1 Build and install kernel modules

1.1 Perform any pending updates:

sudo yum update

If the kernel is updated, reboot the machine.

1.2 Install development tools:

sudo yum group install "Development tools"

1.3 Fix kernel headers location

At the time of writing this How-to, the version of the kernel-devel package doesn't exactly matches the running kernel (uname -r). We worked around this issue by copying headers in the directory matching the version of the running kernel. The version numbers are likely to change (and this issue may be solved), so adapt it your situation.

First, check if this applies to your system:

rpm -qa | grep kernel-devel

kernel-devel-3.9.4-300.fc19.x86_64

uname -r
3.9.4-301.fc19.x86_64

If versions do not match, you can fix (hack) it like this:

sudo su -
cd /usr/src/kernels
cp -a 3.9.4-300.fc19.x86_64 3.9.4-301.fc19.x86_64

1.4 Download lttng-modules

We need to install lttng-modules 2.2.0-rc2 (or later) for compatibility with linux 3.9.4.

wget http://lttng.org/files/lttng-modules/lttng-modules-2.2.0-rc2.tar.bz2
tar -xjvf lttng-modules-2.2.0-rc2.tar.bz2
cd lttng-modules-2.2.0-rc2/
KERNELDIR=/usr/src/kernels/$(uname -r) make
sudo KERNELDIR=/usr/src/kernels/$(uname -r) make modules_install
sudo depmod -a
sudo modprobe lttng-tracer

The module lttng_tracer should be loaded and visible with lsmod. 

Step 2: Install lttng packages

sudo yum install lttng-tools lttng-ust babeltrace lttng-ust-devel

Now, reboot the machine. The service lttng-sessiond should be started automatically, and all required modules should be loaded. Here is some checks that can be done:

$ lsmod | grep lttng_tracer
lttng_tracer          558145  24 lttng_ring_buffer_client_discard,lttng_probe_jbd2,lttng_probe_kmem,lttng_probe_napi,lttng_probe_scsi,lttng_probe_sock,lttng_ring_buffer_client_mmap_overwrite,lttng_probe_statedump,lttng_ring_buffer_metadata_client,lttng_ring_buffer_client_mmap_discard,lttng_probe_irq,lttng_probe_kvm,lttng_probe_net,lttng_probe_skb,lttng_probe_udp,lttng_ring_buffer_metadata_mmap_client,lttng_probe_module,lttng_probe_signal,lttng_probe_vmscan,lttng_probe_block,lttng_ring_buffer_client_overwrite,lttng_probe_power,lttng_probe_sched,lttng_probe_timer
lttng_lib_ring_buffer    50443  7 lttng_ring_buffer_client_discard,lttng_ring_buffer_client_mmap_overwrite,lttng_ring_buffer_metadata_client,lttng_ring_buffer_client_mmap_discard,lttng_tracer,lttng_ring_buffer_metadata_mmap_client,lttng_ring_buffer_client_overwrite
lttng_statedump        30537  1 lttng_tracer
lttng_ftrace           13097  1 lttng_tracer
lttng_kprobes          12911  1 lttng_tracer
lttng_kretprobes       13224  1 lttng_tracer

$ sudo service lttng-sessiond status
Redirecting to /bin/systemctl status  lttng-sessiond.service
lttng-sessiond.service - LTTng 2.x central tracing registry session daemon
   Loaded: loaded (/usr/lib/systemd/system/lttng-sessiond.service; enabled)
   Active: active (running) since Tue 2013-06-04 14:48:53 EDT; 1min 8s ago
  Process: 385 ExecStart=/usr/bin/lttng-sessiond -d (code=exited, status=0/SUCCESS)
 Main PID: 418 (lttng-sessiond)
   CGroup: name=systemd:/system/lttng-sessiond.service
           └─418 /usr/bin/lttng-sessiond -d

Step 3: Make traces with workload-kit

One way to make traces is to use workload-kit. Here is how to install it from sources.

wget http://secretaire.dorsal.polymtl.ca/~fgiraldeau/workload-kit/workload-kit-0.1.13.tar.bz2
tar -xjvf workload-kit-0.1.13.tar.bz2 
cd workload-kit-0.1.13/
./configure --disable-cputemp
make -j12 
sudo make install

Then, the tool lttng-simple can be used to generate a UST trace or a kernel trace for instance:

lttng-simple -k -s -- sleep 1
babeltrace sleep-k/

lttng-simple -u -- /usr/local/share/workload-kit/scripts/ust/wk-heartbeat
babeltrace wk-heartbeat-u/

Happy tracing!

Tracing userspace memory allocation

You may wonder what are the actual memory allocations in a program according to time. Here is a method to trace these operations with the LTTng User Space Tracer (UST). Events are recorded by overloading malloc() and free() with a library that is preloaded with LD_PRELOAD. This library is called "liblttng-ust-libc-wrapper.so". To easy the actual tracing session setup, this feature has been added to the lttng-simple utility of workload-kit v0.1.13. By specifying the option "--enable-libc-wrapper", then the environment is set automatically. Here is quick demo to look at the memory allocations of gnome-calculator. (output of babeltrace is simplified for clarity)

// trace the program
$ lttng-simple -u --enable-libc-wrapper -- gnome-calculator

// display events
$ babeltrace gnome-calculator-u/
[10:48:49.808255177] malloc: { size = 40, ptr = 0xCA8220 }
[10:48:49.808256389] free: { ptr = 0xCA8220 }
...

// count events and look for lost events
$ javeltrace analyze -i ctf gnome-calculator-u/...
number of streams                             1
number of packets                         1,058
number of events                        181,879
number of CPUs                                8
number of lost events                         0

This experiment shows that there are about 182 thousands memory allocation events to start a calculator!

Checking for lost events with javeltrace is recommended. The default buffer size in UST is quite small, and in consequence lost events occurs even with very light load, like starting the calculator with memory allocation tracing. The tool lttng-simple setups buffers of 16MB to make it safer.

The next step is of course to display this data according to time and compare it to physical pages allocated by the operating system with a kernel trace.

Happy hacking!

Augedit prototype

Augeas is a great tool for string to tree transformation. I created a GUI to make it visual and more interactive. The prototype app is called Augedit. It displays the Augeas tree on the left side, and on the the string representation on the right side. By selecting a node in the tree, the label and the value matched are highlighted in the text view. Here is an example with a trivial key/value lens, one record per line.

Behind the scene, it uses span information of the selected path to recover the file content and highlight the key and the value. The app is in Vala and uses Gtk toolkit.

The prototype as of now is only a viewer. This could be extended in many ways:

• Edition capabilities, where the tree and the text are synchronized as the user types
• Providing a view to query and display results
• XPath expression builder, so that they can be validated and then used in scripts
• Highlight the whole match for a sub-tree  The information is available from the span, but I haven't been able to set alpha channel for colors in Gtk.TextView. Using pango/cairo/webkit based widget to display the text may be the solution.

Vala is quite nice, I like the idea of having bare metal binaries and the integration with Augeas with the bindings works great, documentation on valadoc.org is excellent. However, GCC complains because of the C code generated and it's a bit annoying  part of it is my fault (using deprecated stuff, like Gtk.Box() for instance). For more code examples, I'm using yorba projects as reference, like geary and shotwell. Finally, debugging is not as convenient, because of the additional layer of code generation.

The code is on github: https://github.com/giraldeau/augedit

Have fun!

Presenter assists

I was a volunteer at EclipseCon 2013. One of the task consists to help the speaker keep on time, by displaying cardboards showing the remaining time of the session. For fun, I and François Rajotte made a small QML app for that purpose (and most of all to experiment with QML). The app is based on a timer, with color transition when remaining time goes under some threshold. It is really hacky, but it works!

Usage:

• Start or reset the timer: click anywhere in the window
• Full screen: press "F"
• Quit: press "Q"

We definitely should be able to set the start time (not all sessions have the same length) and the list of threshold with custom colors should be customizable. It requires an additional UI component, and those settings should be saved.

As for QML, it's quite cool. The rendering is flicker free and it's quite easy to make animations. We had one issue with keyboard events. We extended a QAction and overloaded the method eventFilter to get key events. The problem is the method always returned "true", as if we should stop forwarding the event to other event filters. It turns out that it was preventing QML to behave properly, because its handler runs after our own. Be aware!

The code is on github: https://github.com/giraldeau/presenter-assists

Paradyn Week 2012 summary

Paradyn Week 2012 was held at the University of Maryland. I went there to see what other folks were doing in the area of debugging and runtime software monitoring with executable binaries modification. I wanted to compare that approach with our current tracing methods.

Dyninst is a set of tools to modify assembly code. It's like a swiss knife for binaries. It can disassemble  them, analyse instructions, recover control flow, and then insert or delete code. It generates code for x86, amd64, ppc32 and ppc64 and few other exotic architectures.

The first presentation was about data flow analysis. The most interesting part in my point of view was the liveness analysis. It computes the set of registers read or written in a function. While tracing, only the subset of registers that actualy contains values are saved. The performance benefit has not yet been evaluated, but the hypothesis is that if fewer registers are saved at each tracepoint, then it will lower the overhead. But, since compilers tries to use as much registers as possible and that under x86 there are very few general purpose registers, probably the number of live registers, on average, is close to the entire set of registers.

Then, there were a talk of Josh Stone from Redhat about integrating Dyninst with SystemTap. The core idea is to use STP scripts and compile them as shared library to instrument userspace applications. The current implementation is able to connect static tracepoints probes to handler functions. For this proof of concept, the handler prints the function name to the console.

There were a talk about debugging at extreme scale. The scale considered is 100k nodes and 1M cores. The idea is to script the debugging phase instead of trying to use interactive debugger. The debugging script is added to the cluster scheduler queue to run later. MRNet, a tree network overlay library, is used to control the debugger. A benchmark shows that setting a breakpoint on 1M cores takes about 200ms! It's also used to gather results with a reduction algorithm to make it also scalable, instead of using only concatenation of results.

The self-propelled instrumentation presentation was about instrumenting distributed applications. It follows the control path and instrument on the fly the application. All the instrumentation is in userspace, using executable patching. If I understood well, when a client connects to a server on a different machine, then a background ssh connection is made to the other host, the instrumentation is injected to the peer process, and the program continues. The instrumentation itself is a callback that is attached to a function. For the demo, the function was performing printf.

Besides that, people were so welcoming, and it was a great pleasure to share ideas. Cherry blossom are everywhere here in Washington and College Park, we should definetely have more in Montreal!

TCP socket blocking behavior

Here are some experiments results of blocking behavior of TCP applications. Blocking is a special state in which a process is waiting for I/O and removed from the scheduler queue. When the data is available, the process is woken up. In the case of distributed applications, the network latency is likely to cause blocking. To understand the behavior of such applications, a small experiment is made with netcat on Linux. System events are recorded with LTTng and network events are recorded with tcpdump. To simulate the network latency, the Linux traffic shaper is used. Here is the script used as the test case.

#!/bin/sh
tc qdisc add dev lo root netem delay 100ms
netcat -l localhost 8765 > /dev/null &;
echo "lttng" | netcat localhost 8765
tc qdisc del dev lo root

Here, the traffic shapping command sets the latency of packets to 100ms on the loop-back interface. The first netcat process is configured to listen on port 8765. The server exits immediately when a message is received. Next, the netcat client is spawn and a small string is transfered. The last command removes the traffic shapping configuration. The Linux kernel used is 2.6.38 on x86_64.

Tracing this script reveal three main blockings, as reported by the blocking analysis module of flightbox.

# server process
Blocking report for task /bin/netcat [7495]
Start            Duration (ms)        Syscall Wakeup
8073461215283          300,873     sys_accept SOFTIRQ

# client process
Blocking report for task /bin/netcat [7497]
Start            Duration (ms)        Syscall Wakeup
8073461820815          200,155     sys_select SOFTIRQ
8073662056512          200,135       sys_poll SOFTIRQ

The next figure shows blockings occurring in the system, including messages sent at each steps.

The server process create a new AF_INET socket, binds it and start to listen on the selected port. The accept is then performed for an incoming connection. From the trace, we observe that sys_accept blocks for about 300ms. This delay is very close to three times the network latency and is also almost equal to the process duration. Once the accept returns, the read on the socket doesn't block and the process exits.

In the case of the client, it creates the socket, then perform a sys_connect to the server. The connect returns immediately the value EINPROGRESS without blocking. The next step performed is a sys_connect, in which the client blocks for about two times the network latency. When the select returns, the actual message is sent to the server without blocking and the socket is closed. Finally, the client waits on sys_poll for about twice the network delay.

From this observation, the sys_accept performed by the server blocks until the final handshake ACK is received. Hence, unfinished handshake is completely hidden from the application and handled at the OS level. When the read is done, the data is already buffered, such that the read doesn't block in this case. In the case of the client, the connect system call returns in an optimistic fashion. The wait for the socket to be ready is differed to a select system call. This may allow many connect to be performed simultaneously. As for the poll, this may be related to the tear-down procedure of the socket, waiting for the final FIN from the server.

In the case of the traffic shaper used, the delay between consecutive packets is preserved. For example, the client sends three packets when the sys_select returns in a short burst. Hence, this experiment may not highlight all possible blockings. An alternative to traffic shaper is the iptables NFQUEUE. It allow to forward each packet in userspace for arbitrary processing. More on this in the next blog.

Tracing MPI application

While preparing labs for the Parallel Systems course at Polytechnique, I had the chance to refresh my MPI knowledge. One of the activity consist to compare communication patterns in a MPI application. For this purpose, the MPI library can be linked with special library to record all communication. Jumpshot is the graphical viewer for the trace. I wanted to compared traces obtained from MPE and compare it to a kernel trace.

First, some technical details on how to instrument MPI program, because it's not so obvious after all and documentation is sparse. I tried MPICH and OpenMPI as MPI implementation. I would recommend MPICH because it seems to provides better error message, which are very valuable to understand failures. In addition, on Fedora, MPE library is built-in in the MPICH package, which is not the case for OpenMPI. On Ubuntu, MPE library must be downloaded and installed by hand [1] because there is no binary package for it. As for the autoconf for the project, I reused m4 macro cs_mpi.m4 from Code Saturne [2] with the following options to configure. By linking to llmpe, the library will ouput suitable file for Jumpshot.

CC=mpicc LDFLAGS="-L/usr/local/lib" LIBS="-llmpe -lmpe" ./configure

The experiment consists in a small MPI application that exchange grid boundaries in 1D cartesian decomposition using blocking send and receive. 4 process are launched on the same host. The first figure shows a zoomed view of execution and messages exchanged between process according to time. The second figure shows a statistic view for an interval, in which the time spent in each state is summed. In one look, one can see what is the relative taken for the communication, which is very handy to understand performance.

The same application has been traced with the LTTng kernel tracer. While the program is computing and exchanging data with neighbors, no system calls are performed to transfer the data. In fact, between process on the same hosts, MPICH uses shared memory for communication, obviously to achieve better performance. This example shows that it may not be possible to recover relationship between processes that communicates through shared memory. One thing to note is that numerous polls on file descriptors are performed, probably for synchronization. Maybe the relationship can be recovered from there.

Jumshot Timeline view (green: recv, blue: send)

Jumshot Histogram view (green: recv, blue: send)

LTTv control flow view (green: userspace)

Would it be possible to trace shared memory accesses directly? A recent kernel feature allows to trace memory map I/O (MMIOTRACE). It works by resetting the flag that indicates a page is in memory, such that a page fault is triggered each time a page is accessed. The page fault handler is instrumented to record those events. This technique may be a hint on how to recover shared memory process relationship. More on this later.

In conclusion, MPI instrumentation with MPE helps to understand runtime performance behaviour of MPI application. The same results can't be obtained with the current kernel tracing infrastructure found in LTTng.

[1] ftp://ftp.mcs.anl.gov/pub/mpi/mpe/mpe2.tar.gz
[2] http://research.edf.com/research-and-the-scientific-community/software/code-saturne/introduction-code-saturne-80058.html