vendredi 31 mai 2013

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!

jeudi 28 mars 2013

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

mercredi 28 mars 2012

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!

mardi 24 janvier 2012

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.

mercredi 16 novembre 2011

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

mardi 26 juillet 2011

Common Trace Format Bitfields

The Common Trace Format (CTF) will be the default format of the next release of LTTng 2.0. This new trace format is able to write data at the bit level to optimize space usage of each field. Such sub-byte packed bits is called a bitfield.

Endianness of the bitfield follows the native endianness of the architecture where the trace is obtained. Big endian (BE) and little endian (LE) are supported. But how does the bits are written into the trace? According to the documentation in include/babeltrace/bitfield.h:

The inside of a bitfield is from high bits to low bits.

On big endian, bytes are places from most significant to less significant.
Also, consecutive bitfields are placed from higher to lower bits.

On little endian, bytes are placed from the less significant to the most
significant. Also, consecutive bitfields are placed from lower bits to higher
bits.

To make sure I understood correctly, I created an example based on the current implementation in babeltrace. The structure has three fields. Each field is followed by it's length in bits.

struct x {
    unsigned int a : 4;
    unsigned int b : 32;
    unsigned int c : 4;
}

The total size of the structure is 40 bits or 5 bytes. For the example, following values are assigned to the fields to be able to spot them easily:

x.a = 0x0000000E;
x.b = 0xA1B2C3D4;
x.c = 0x0000000F;

Then, writing those values in a byte array in big and little endian gives the results in the table below. The binary and hexadecimal reprensentation of consecutive bytes are displayed.


Big endian
0b11101010 0xEA
0b00011011 0x1B
0b00101100 0x2C
0b00111101 0x3D
0b01001111 0x4F
0b00000000 0x00
[...]

   

Little endian
0b01001110 0x4E
0b00111101 0x3D
0b00101100 0x2C
0b00011011 0x1B
0b11111010 0xFA
0b00000000 0x00
[...]

Big endian is simple, because the bitfield is written sequentially. The first byte 0xEA starts with the four bits if the a field, followed by the first four bits of the b field. Notice that in consequence all subsequent bytes of the b field are shifted. The last byte starts with the last four bits of the b field. The c field fills the rest of the last byte. All bytes that follow are untouched.

As to little endian, the first byte ends with the a field. Then, the b field is written, but the most significant bit is found on the second half of the last byte. Notice that tbe bytes and written backwards, also shifted by four bits. The third field c is placed in the upper half of the last byte.

Happy hacking!