Function graph tracing with LTTng

FTrace has the ability to hook function entry and return in the kernel. I did a small prototype demonstrating the possibility of recording these events with LTTng, and viewing the result with TraceCompass.

The idea is to register callbacks using register_ftrace_graph(). This symbol is not exported, therefore we use kallsyms to lookup the address at runtime. The callbacks contains themselves a tracepoint that records entries and returns. The kernel module implementation lttng-fgraph.c is quite simple. It limits the tracing to the normal kernel mode (no interrupt) and the function to hook is hardcoded (do_sys_open()) for prototyping purpose.

The implementation of the analysis module in TraceCompass is relatively simple (LttngFtraceCallStackProvider.java). In fact, it consists mostly to define entry and return events, and how to decode the event payload. In order to show function names instead of addresses, I implemented a symbol provider for kallsyms. It walk the trace directory to find the kallsyms file and parse it to map addresses to symbols. The user just needs to copy /proc/kallsyms below the trace directory, like this:

mkdir my-trace/kernel/syms
sudo cat /proc/kallsyms > my-trace/kernel/syms/kallsyms

Sudo (root) is required, because symbol addresses are usually hidden by default. The kallsyms file must be within its own directory, otherwise the trace parser will try to open the kallsyms file as a trace stream and will report an error.

Here is the result of some open system call on the system. Because the views are synchronized, the open system call interval of the processes shown in the control flow view overlap the call stack graph. It looks great, isn't?

However, the overhead of function tracing is somewhat high. For each function call, about 300ns are spent writing trace events, which may represent more time than the processing done in the function itself. To address the situation, FTrace has the ability to record an event only of the delay inside the function is greater than a given threshold. The call graph is no longer the exact representation of the execution, but it contributes to reduce the overhead and the trace size by not recording short duration functions, while still identifying slow functions.

At the moment, FTrace does not exports the registration functions, because external users were not intended. Only one set of hooks can be defined at a time, so one cannot use ftrace and lttng at the same time. In the future, that could be a nice extension to FTrace to make it more general and allow other tracers to use the function graph. For instance, kprobe could get callbacks not only on function entry and return, but also on each of its children.

Real-life real-time problem

I installed Linux RT on the Jetson TK1 last month. Since then, cyclictest is running to test that latency is always correct. The maximum wake-up latency is usually ~100us, and it can run like that for a long time. However, on rare occasion, a latency of ~8ms occurs when running for a long period of time (about one week). This kind of problem is tricky to find without proper tools. Here is how I found the problem.

I configured LTTng kernel and userspace tracing to continuously trace the system. The kernel trace records scheduling events and system calls while the userspace trace indicates the location of the missed deadline. When a high latency is detected, the trace is stopped and a snapshot of the trace buffers are written on the disk. I let the system running with tracing enabled for a couple of days, and then a snapshot was created, indicating that the problem occurred.

The following figure shows the result of the traces loaded in TraceCompass. We can see this bug is the result of interactions between three tasks, namely ktimersoftd/2, irq/154-hpd and cyclictest. The cyclictest wake-up signal is delayed for a long time. This signal puts back the task in the running queue, and it is delivered by ktimersoftd/2. The ktimersoftd task has lower priority than irq/154-hpd that happens to run for a long time. Even though the cyclictest has higher priority than the IRQ thread, as long as cyclictest is in the wait queue, the priority has no effect. Priority inheritance does not work here because we don't know in advance that ktimersoftd will actually wake-up a high priority task.

Obviously, the ktimersoftd threads should have greater priority than other IRQ threads as they are required by cyclictest to meet its deadline. There are few questions left: how the default priorities are defined, what is actually doing the irq/164-hpd task, and does increasing ktimersoftd priority will fix the issue? More investigation is required.

In the meantime, if you want to look for yourself, the trace is here. Cheers!

Real-time setup on Jetson TK1

The Linux kernel is a popular operating system for real-time applications. Here is a summary of experimentations with the real-time kernel on the Jetson TK1 board from NVIDIA.

Setup the board

The Jetson TK1 from an internal memory. NVIDIA supplies a script to "flash" the device with the file system root and the kernel. I use the manual method from the NVIDIA Jetson TK1 documentation. Download the Driver Package and the Sample Root File System, and follow the Quick Start Guide. You should have a working system after these steps. 

I tried to use the JetPack installer to flash the device, but it requires Ubuntu 14.04, the procedure failed and it was re-downloading the huge files, so I don't recommend it. Also, I tried the procedure to use the SD card instead of the internal memory of the board and that failed too, so I stick with flashing the internal memory. 

Compile linux-rt

Clone Linux-RT from git.kernel.org:

git clone https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-rt-devel.git

cd linux-rt-devel

git checkout linux-4.4.y-rt-rebase

While it downloads, install the cross-compiler for ARM (the "hf" in arm abi hf stands for hard-float, meaning that the compiler will output code optimized for on-chip floating point arithmetic):

sudo apt-get install gcc-arm-linux-gnueabihf

Configure the kernel. When cross-compiling, the ARCH and CROSS_COMPILE variables must be set.

• Under "Kernel Features ->  Preemption Model", select the preemption level (i.e. PREEMPT_RT_BASE)
• Under "Kernel hacking" uncheck "Debug preemptible kernel" (known to cause slowdown)

# update configuration

make ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- tegra_defconfig
make ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- menuconfig

# compile
make -j12 ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- 

make -j12 ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- dtbs
# install the modules into the rootfs (adjust according to your setup)
sudo make ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- INSTALL_MOD_PATH=../Linux_for_Tegra/rootfs/ modules_install

There should be a directory created under Linux_for_Tegra/rootfs/lib/modules/
The last step consists to flash the device with the fresh kernel. However, the flash.sh script dit not work correctly for me. The options "-K " and "-d " do not configure the rootfs correctly. This step must be done manually and the settings are not overwriten by the flash script. Beware that the script apply_binaries.sh will copy the zImage from the kernel directory. To avoid using the previous kernel by mistake, replace the default zImage in the kernel directory with your own.

The Device Tree Blob (DTB) describes the hardware addresses that are specific to the device. Previously, one had to write these memory locations in C, whereas it is done declaratively and converted to a binary format. In my understanding, it simplifies the support of a wide range of devices. I were not able to boot the board without the proper DTB file set in the bootloader.

sudo cp arch/arm/boot/zImage ../Linux_for_Tegra/rootfs/boot/

sudo cp arch/arm/boot/zImage ../Linux_for_Tegra/kernel/

sudo cp arch/arm/boot/dts/tegra124-jetson-tk1.dtb ../Linux_for_Tegra/rootfs/boot/

Setup the bootloader

Edit the bootloader configuration file Linux_for_Tegra/rootfs/boot/extlinux/extlinux.conf to set the FDT field with the path of the Device Tree Blob (DTB) (do not change the other fields):

MENU TITLE Jetson-TK1 eMMC boot options LABEL primary MENU LABEL primary kernel LINUX /boot/zImage FDT /boot/tegra124-jetson-tk1.dtb

Then, put the device in recovery mode (hold the recovery button while pressing reset, the board should be displayed in dmesg) and execute the usual flash command:

cd Linux_for_Tegra/

./flash.sh jetson-tk1 mmcblk0p1

After the board reboots, it should run the real-time kernel. The board has a serial port and spawning minicom with a serial-to-usb device allowed to see the boot logs. This is required because the screen is blank at this early boot stage.

I still have an issue with the CONFIG_PREEMPT_RT_FULL. Without the serial cable, it would be not possible to diagnose the problem.

[    5.170764] Unable to handle kernel paging request at virtual address ffefe574
[    5.186139] kernel BUG at kernel/locking/rtmutex.c:1011!
[    5.981440] Fixing recursive fault but reboot is needed!


I use instead CONFIG_PREEMPT_RT_BASE, but I don't know exactly what is the difference between the full RT config, this is something to investigate.

MachineKit LTTng kernel trace

How does MachineKit execution look like at the system level? Here are some observations done using an LTTng kernel trace on Linux preempt-rt 4.1.13-rt15 on a 4 cores machine. The workload traced is the abs.0 unit test. This test spawns halcmd, simulating the position control of a motor (or something). Here is the command:

cd machinekit/
. scripts/rip-environment
cd tests/abs.0/
halcmd -v test.hal

The overall command takes 3.3s to complete. Let's check what's in the trace.

First, the rtapi processing takes about 600ms to execute and is shown in Figure 1. One of the related process, named fast:0, seems to do the actual real-time job and is shown in Figure 2. This process sleeps periodically using the system call clock_nanosleep(). I observed a wake-up latency of about 30us and the thread itself runs for about 2-3us in user-space before returning to sleep.

Figure 1: Overview of the rtapi execution.

Figure 2: Real-time process with period of about 300us.

The scripts and utilities to manage the test environment behave quite differently than the RT process. In particular, there is a bunch of processes that interact for very short durations, namely halcmd and rtapi, as shown in Figure 3. They perform sendto() and recvfrom() system calls, probably for round-trip communication. Maybe using shared memory could help here to streamline the communication. There is numerous sleep of 10ms to 200ms performed by halcmd in midway. 

Figure 3: Interactions between halcmd and rtapi.

There is a pattern of fork-exec-wait done by the script realtime shown in Figure 4. This script spawns inivar, flavor and halrun executables, together running for more than 400ms. Using programmatic API instead of spawning executables would make the processing more efficient. 

Figure 4: Repeated fork-exec-wait pattern.

Finally, there is a giant 2.5s sleep at the end of the test, shown in Figure 5. It represents therefore 75% of the test execution time. This kind of sleep is usually done for quick-n-dirty synchronization, but should be replaced by wait for the actual event required to execute as quickly as possible. This way, the time to run the unit tests can be decreased significantly, possibly representing greater productivity for developers.

Of course, if we had a user-space trace in addition to the kernel trace, we could have a greater insight of the internal state of machinekit. But even without, we can observe interesting behavior. The next step will be to actually plug and control some actual hardware in real-time.

Why malware detection based on syscalls n-grams is unlikely to work

In the field of computer security, it was suggested to use n-grams of system calls to detect malware running on a computer. Let's demonstrate that there is no relationship between n-gram counts and malicious behavior.

False-negative example. The first trace is a weather app that opens a config file, then performs some remote procedure call to get the data, and then closes file descriptors. The other is the same sequence, but for a malicious app that gained root privilege by some means, and sends the content of the password file.

Trace A1: open(“app.conf”); read(); connect(); send(); recv(); close(); close()

Trace A2: open(“/etc/passwd”); read(); connect(); send(); recv(); close(); close()

The probability of each n-gram is trivially the same for the same sequence. Therefore, the algorithm fails to detect the malware.

False-positive example. Both sequences are functionally equivalent and non-malicious, but the second trace reduces the maximum number of opened file descriptor at one time.

Trace B1: open(); open(); open(); read(); read(); read(); close(); close(); close()

Trace B2: open(); read(); close(); open(); read(); close(); open(); read(); close()

Let’s use Python to generate all n-grams of size 3.

ngrams = [x for x in itertools.product(['open','read','close'],['open','read','close'],['open','read','close'])]

                                        B1 B2 (B2 sym diff B1)

open  open  open  1 0  \empty
open  open  read  1 0  \empty
open  open close  0 0
open  read  open  0 0
open  read  read  1 0  \empty
open  read close  0 3  \empty
open close  open  0 0
open close  read  0 0
open close close  0 0
read  open  open  0 0
read  open  read  0 0
read  open close  0 0
read  read  open  0 0
read  read  read  1 0  \empty
read  read close  1 0  \empty
read close  open  0 2  \empty
read close  read  0 0
read close close  1 0  \empty
close  open  open  0 0
close  open  read  0 2  \empty
close  open close  0 0
close  read  open  0 0
close  read  read  0 0
close  read close  0 0
close close  open  0 0
close close  read  0 0
close close close  1 0  \empty

total              7 7

The n-gram counts for both sets are totally disjoints. Therefore, the algorithm will wrongly detect the trace B2 as malware code, while it is in fact the result of a simple optimization.

Moreover, a malicious app can trick the detection by calling dummy system calls randomly, which will swamp the potentially mallicious sequences. Because each n-gram probability will be non-statistically significant, the algorithm will fail to identify the change of behavior, and classify it as malware.

Therefore, we conclude that this technique is unlikely to provide any benefits to identify malware automatically.

Full stack Python tracing

The project profile-python-ust allows to record function call and return from Python interpreted code using LTTng-UST. As an example, consider this foo.py code (calling itself bidon.py that just print something on the console):

import bidon

def baz():
    bidon.bidon()

def bar():
    baz()

def foo():
    bar()

if __name__=='__main__':
    foo()

The trace produced is:

python:call: { cpu_id = 7 }, { co_name = "" }
python:call: { cpu_id = 7 }, { co_name = "foo" }
python:call: { cpu_id = 7 }, { co_name = "bar" }
python:call: { cpu_id = 7 }, { co_name = "baz" }
python:return: { cpu_id = 7 }, { }
python:return: { cpu_id = 7 }, { }
python:return: { cpu_id = 7 }, { }
python:return: { cpu_id = 7 }, { }

However, the tracing hooks into CPython are not called for external C modules. Therefore, we loose track of what is going on. For instance, Cython compiles Python code as a native shared library for greater efficiency. To overcome this limitation, I compiled the Cython foo.pyx code using GCC function instrumentation. Here is the setup.py file (The same code gets compiled twice, with and without instrumentation):

from distutils.core import setup
from Cython.Build import cythonize
from distutils.extension import Extension

ext = [
    Extension('foo1', ['foo1.pyx'],
              extra_compile_args = ['-g'],
    ),
    Extension('foo2', ['foo2.pyx'],
              extra_compile_args = ['-finstrument-functions', '-g'],
    ),
]

setup(
    ext_modules = cythonize(ext),
)

And then I invoked both modules foo1.foo() and foo2.foo(), with the lttng-ust-cyg-profile instrumentation, that hooks on the GCC instrumentation. I also enabled kernel tracing, just for fun. Both traces (kernel and user space) are loaded in an Trace Compass experiment.

We see in the screenshot below the users space stack according to time for the foo1 and foo2 executions. In the first execution, we see the entry point of inside foo1.so and the invocation of Python code from the library, but function calls inside foo1.so are not visible. In the second execution, both the Python and the GCC instrumentation are available, and the complete callstack is visible. The higlighted time range is about 6us and corresponds to the write() system call related to the print() on the console. We can see the system call duration and the blocking in the control flow view.

Unfortunately, symbols can't be resolved, because base address library loading can't be enabled at this time with Python instrumentation, due to this bug.

This was an example how three sources of events finally create a complete picture of the execution!

EDIT:

A Cython module can call profile hook of the main interpreter. Call cython with the profile option, and compile the resulting code with -DCYTHON_TRACE=1. This can be done in setuptools with:

 cythonize(ext_trace, compiler_directives={'profile': True}),

Thanks to Stefan Behnel for this tip!

How Linux changes the CPU Frequency

The ondemand governor adjust the processor frequency making a trade-off between power and performance, and is the implementation of Dynamic Frequency Scaling under Linux. However, it was also causing unexpected delays in my performance benchmarks. The following figure shows the delay density of RPC requests for the CPU frequency governor ondemand and performance. Delay variation is lower when the CPU frequency is fixed.

I wanted to visualize how the frequency changes according to time and scheduling. I used LTTng to record power_cpu_frequency and sched_switch events. I loaded them in Trace Compass, and defined the analysis declaratively using XML (available here). The CPU frequency is shown in shades of red (stronger means higher frequency) and in green whether the CPU is busy or idle. (you guessed correctly, holiday season is coming). We see in the following figure that it takes some time for the frequency to ramp-up.

In fact, changing the CPU frequency is equivalent to distorts the elapsed time of the execution. Timestamps in the trace are in nanoseconds instead of clock cycles, but to compare executions, the base should be clock cycles instead. We could scale the time using the frequency events to approximate the time in processor cycles.

The task kworker, woken-up from a timer softirq, changes the CPU frequency. The kworker thread runs with a varying period, typically between 4ms and 20ms. The algorithm seems to take into account the average CPU usage, because if the CPU does rapid context switch between idle and busy, the frequency never reaches the maximum.

Therefore, a task performing frequent blocking/running cycles may run faster if it shares the CPU with another task, because the average CPU usage will increase and frequency will be set accordingly. We could also estimate the relative power cost of a segment of computation with great precision.

In conclusion, disabling frequency scaling for benchmarks should reduce variability. Here is how to do it on recent Linux kernels:

set_scaling_gov() {
        gov=${1-performance}
        for i in $(ls -1 /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor); do
                echo ${gov} | sudo tee $i > /dev/null
        done
}

Here is the view for the whole trace. Happy hacking!

LinuxCon 2014, Düsseldorf

Distributed Active Path from Kernel Trace

I presented recent work about the recovery of active path of a distributed program, only using a kernel trace. The result is a time-view of the execution across computers. One of the most interesting result is the Django Poll three-tiers app, including an Apache web server and a PostgreSQL database. Client is simulated by scripting with Mechanize. The screen shot shows the execution for the POST, where a large sync is visible near the end of the sequence, necessary for the update SQL statement. 

Declarative views from user-space trace with Trace Compas

Geneviève Bastien presented how to use LTTng-UST and Trace Compas to create a time view of the state of an MPI computation. The MPI program simulates unbalanced computation, where the green represent work, and red is wait at the barrier. Multiple cycles are shown, and all the views are synchronized, which is handy to analyse the application at multiple level at once. In the following figure, we see below that the wait at the barrier (in red) is actually implemented using a busy loop calling non-blocking poll() system call, shown on top. We observed this behavior with the OpenMPI library, and we think it is intended to reduce the latency at the expense of power and resource efficiency.

Below: MPI imbalance application state (green: compute, red: wait). Above: corresponding kernel trace, including a zoom on the busy wait.

Preemption analysis across host and virtual machines

Execution in virtual machines is subject to higher level of variation in response time. Geneviève Bastien presented the virtual machine analysis, that shows the preemption crossing virtual machines boundaries, the research result of former student Mohamad Gebai. A process in the VM may appear to run while it is not, because the process representing its virtual CPU on the host is be preempted. The host and the VMs are traced at the same time, and traces are synchronized. The global view of the resources allows to pinpoint preemption cause given a task, whenever the other task is local, on the host or inside another virtual machine. The following figure shows qemu processes on the host and traces from within the host. We clearly see a gettimeofday() that is much longer that one would expect (13ms instead of ~200ns), and the reason is that there is another process, in another VM, that was running for that time, and the preemption cause is shown below.

Total view of the system, crossing virtual machine boundaries.

ftrace

Sten Rosted from RedHat presented the inner working of ftrace. It is a framework to hook into each function in the kernel. The kernel is compiled with gcc -pg option, that adds a call to mcount() at the beginning of each function, but this call is replaced by nops. The space left in each function header is patched at runtime to jump to the instrumentation. This framework is used by kprobe, but the ftrace backend can be used directly instead.

folly

Ben Maurer from Facebook presented efficiency and scalability issues they face in their environment. Performance in accepting connections is critical. He mentioned that getting the next available file descriptor is a linear search that hurts the performance. He also shows a method to decrease the number of scheduling switch of workers by replacing pthread condition wait, and improving load distribution among threads. I liked his quantitative approach, always evaluating both kernel and user-space solutions to the same problem.

Cycle accurate profiling using CoreSight hardware trace

Pawel Moll from ARM presented the CoreSight instruction tracing capabilities. The processor records branch taken and the number of cycles taken by each instructions. He demonstrated a prototype of cycle accurate (i.e. exact cycle count) profiler. The trace decoding is somewhat cumbersome, because the code memory must be reconstructed offline to resolve address symbols, and the complete toolchain requires proper integration, but still an impressive demonstration.

Thanks to NVIDIA!

I also got a JETSON TK1 big.LITTLE board from NVIDIA. I will be able to test heterogenous traces experiments (x86, arm), a very common case for mobile and cloud computing. I will also be able to test the CoreSight tracing. Thanks NVIDIA!

Ubuntu login analysis

I'm tracing a lot these days, and in the viewer, I need to scroll a lot to get to the interesting stuff in the control flow view. Today, I checked all these processes for fun. In fact, it's related to landscape triggered on Ubuntu login. To display the message about system usage and updates (which I think is great), landcape calls numerous sub-programs, for a total of about 250ms on my system. It's something one should keep in mind if SSH commands are repeated in a tight loop: the maximum rate is about 4 commands per seconds. Hopefully, Fabric reuses SSH connection! ;-)

Ubuntu login greeting

The active path of the computation of the login greeting

Pinpoint memory usage of Java program with Eclipse Memory Analyzer

My Java program was using a lot of memory. An object was holding a reference on a large temporary data structure, even after it was out of scope. It is indeed difficult to understand what prevent the garbage collection to do its job. Here is how I found out.

• Download and extract Eclipse Memory Analyzer (MAT).
• Download the HeapDump.java class and insert a call to HeapDump.dumpHeap() after the point your think the memory should be released.
• Run the instrumented program. The resulting file size may be rather large (seems to be the hole VM memory), so make sure you have enough free space.
• Open it in MAT. (Notice: I was experiencing a hang bug on Ubuntu 14.04, dismiss the initial report dialog and do not generate HTML reports, it seems to trigger the bug). Click on Dominator Tree.
• Once you found the offending object, right click on it and select Path to GC Roots > with all references. This will display the references that prevent the GC to free this object.
• Fix the code and you can start over to verify that the problem is indeed fixed ;-)

The following screenshots shows an example of the tool usage for my problem. The class TmfNetworkEventsMatching matches send to receive network events in a trace. Unmatched packets are kept temporarily in memory. However, the old unmatched packets were never freed. In the Dominator Tree, we see that TmfNetworkEventsMatching is 40 bytes (Shallow Heap), but holds around 1.2MB of objects (Retained Heap). The Path to GC Roots highlights that a reference of TmfNetworkEventMatching is kept inside TmfRequestExecutor. In this case, a missing call to dispose() was preventing the release of resources. Other resources are auto-closable, except for one of them, which needs manual call to dispose(). Thank you MAT!

Dominator Tree

Path to GC Roots

Performance comparison of CTF trace readers

I'm implementing a kernel trace analysis using the Java CTF reader, and I wanted to know if I would increase the performance by going with the babeltrace reader in C. Here are my findings.

One of the expansive step of trace analysis is the actual trace reading. It consists to read the binary trace and retrieve the timestamps, the event type and the value of each fields. The event is then added to a priority queue for reading multiple streams in order. We compare three trace readers, namely the Babeltrace reader 1.2 (C implementation, dummy output format), the Java CTF reader and the Eclipse TMFEventRequest (which uses the Java CTF reader as back-end). We compare the trace reading in cache cold conditions (drop_caches prior to reading) to when the trace is resident in page cache. I ensure that the lazy loading of fields values are effectively loaded in all cases, but without printing the content. The trace size is 855MB and contains 22 million kernel events from a Django web app benchmark (recorded with lttng), and it takes between 20s and 80s to process the trace. The drive used is an SSD Crucial M500 1TB, and the host is an i7-4770 with 32GB of RAM. The following figure shows the performance results in thousands of events per second.

We observe that babeltrace is roughly 2 times faster than the CTFTraceReader in Java, and about 3.5 times faster than TmfEventRequest. I measured also the CPU usage, and the processing is mostly serial and single threaded in every cases, so babeltrace seems effectively more efficient.

The other important observation is that trace parsing is CPU bound, not I/O bound. Reading a trace from a hard drive is certainly I/O bound, but it's not the case with SSD. The difference between cache cold and cache hot is between 2% and 5% either in Java or in C. It means we could probably speed-up the reading using parallel threads.

In conclusion, both the C and the Java libraries provides acceptable performance level for CTF trace reading. For high-performance processing, the babeltrace library is preferable. The CTFTraceReader provides nonetheless a good performance, and may be a compromise between the rapid development and runtime efficiency. If abstracting the trace source is a requirement, then TMF is what you need, but you now know the cost of this additional flexibility. Yours to choose!

Notice: the TMFEventRequest can be done either with ExecutionType.FOREGROUND or ExecutionType.BACKGROUND. The background parameter introduce delays (sleeps) and reduces the throughput. Use the foreground parameter to reduce processing time and improve UI interactivity, but uses background for low priority processing.

System-level profiling of APT

APT is the package manager of Debian based distributions. Understanding where the time is spent installing a package is difficult, because there are numerous process involved. We discuss limitations of profiler tools and present system-level trace analysis that highlight waiting between tasks.

Callgrind is a profiler that helps to find hotspot in the application. One limitation of a profiler is that the time spent waiting is not taken into account, for instance I/O, resources or other tasks. This situation is shown in figure 1, where we traced the command "sudo apt-get install tree --yes". The actual computation done in the apt-get process accounts for 63% of the elapsed time, while waiting time is about 37%. The callgrind results covers only instructions from the application, not the waiting time.

Figure 1: State of apt-get process according to time.

How to effectively understand what the application was waiting for? For this matter, we performed a waiting dependency analysis on all tasks on the system. The event sched_wakeup indicates the waiting source. Figure 2 shows the result of waiting dependencies among tasks for the command.

Figure 2: Overview of  apt-get waiting dependencies according to time.

The analysis resolves waiting time recursively. In this run, apt-get process is waiting for dpkg, and it accounts for about 20% of the execution time. Figure 3 shows the wait I/O that occurs in dpkg, up to the kernel thread responsible for the file system journal of the partition on which the I/O is performed.

Figure 3: I/O wait of dpkg according to time.

Another interesting part of the execution is the update of man database performed by mandb. Figure 4 shows that about 200 threads are spawned. In this case, the overhead of starting the threads and setup communication pipe is high compared to the amount of actual work, in consequence running time could be greatly improved by using a thread pool instead.

Figure 4: Execution of mandb according to time.

We located the code responsible for creating all these threads and processes using perf callchain. It seems to be related to how the library libpipeline is working. Here is an example of an interesting call stack:

7ffff729a30b     __execvpe (/lib/x86_64-linux-gnu/libc-2.17.so)

7ffff75a4de4     pipecmd_exec (/usr/lib/x86_64-linux-gnu/libpipeline.so.1.2.2)

409813           [unknown] (/usr/local/bin/mandb)

7ffff75a4e59     pipecmd_exec (/usr/lib/x86_64-linux-gnu/libpipeline.so.1.2.2)

7ffff75a662a     pipeline_start (/usr/lib/x86_64-linux-gnu/libpipeline.so.1.2.2)

408d96           find_name (/usr/local/bin/mandb)

40449c           test_manfile (/usr/local/bin/mandb)

404708           testmandirs (/usr/local/bin/mandb)

405035           update_db (/usr/local/bin/mandb)

40a1c6           mandb (/usr/local/bin/mandb)

40a4fb           process_manpath (/usr/local/bin/mandb)

403777           main (/usr/local/bin/mandb)

7ffff71f9ea5     __libc_start_main (/lib/x86_64-linux-gnu/libc-2.17.so)

403b09           _start (/usr/local/bin/mandb)

At the end of apt-get execution, there is a sleep of 500 ms, shown in blue in the figure 2. Here is the location in the code of this nanosleep, again using perf callchain feature: 

ffffffff816cc0c0 __schedule ([kernel.kallsyms])

ffffffff816cc799 schedule ([kernel.kallsyms])

ffffffff816cb66c do_nanosleep ([kernel.kallsyms])

ffffffff810827f9 hrtimer_nanosleep ([kernel.kallsyms])

ffffffff8108292e sys_nanosleep ([kernel.kallsyms])

ffffffff816d616f tracesys ([kernel.kallsyms])

7ffff72978c0     __GI___libc_nanosleep (/lib/x86_64-linux-gnu/libc-2.17.so)

7ffff7b8ac95     pkgDPkgPM::DoTerminalPty(int) (/usr/lib/x86_64-linux-gnu/libapt-pkg.so.4.12.0)

7ffff7b93720     pkgDPkgPM::Go(int) (/usr/lib/x86_64-linux-gnu/libapt-pkg.so.4.12.0)

7ffff7b26585     pkgPackageManager::DoInstallPostFork(int) (/usr/lib/x86_64-linux-gnu/libapt-pkg.so.4.12.0)

415a1b           [unknown] (/usr/bin/apt-get)

418dfc           [unknown] (/usr/bin/apt-get)

7ffff7af96c2     CommandLine::DispatchArg(CommandLine::Dispatch*, bool) (/usr/lib/x86_64-linux-gnu/libapt-pkg.so.4.12.0)

40a2ec           [unknown] (/usr/bin/apt-get)

Here is the detail of pkgDPkgPM::DoTerminalPty() function from apt/apt-pkg/deb/dpkgpm.cc:

/*

 * read the terminal pty and write log

 */

void pkgDPkgPM::DoTerminalPty(int master)

{

   unsigned char term_buf[1024] = {0,0, };

   ssize_t len=read(master, term_buf, sizeof(term_buf));

   if(len == -1 && errno == EIO)

   {

      // this happens when the child is about to exit, we

      // give it time to actually exit, otherwise we run

      // into a race so we sleep for half a second.

      struct timespec sleepfor = { 0, 500000000 };

      nanosleep(&sleepfor, NULL);

      return;

   }

   if(len <= 0)

      return;

   FileFd::Write(1, term_buf, len);

   if(d->term_out)

      fwrite(term_buf, len, sizeof(char), d->term_out);

}

The comment mentions a possible race, but the caller may be fixed to account for this situation. IMHO, this function should not sleep if an error occurs while reading the file descriptor, and should instead return immediately.

This was a small example of what can be achieved with the waiting dependency analysis from a kernel trace. The analysis plug-in will be available soon in Eclipse Linux Tools, and uses standard tracepoints from the Linux kernel, recorded with LTTng. I hope that this information will help the community to improve performance of installing packages with APT. 

Cheers!

The APT licence plate! (thanks to Yannick)

How slow is Java reflection?

I use Java reflection for trace analysis, as a way to call hooks when specific events are encountered. I wanted to know the overheard related to using such dynamic invocation. First, here is a small example of a trace event handler.

public class FooTraceEventHandler extends TraceEventHandlerBase {

  public FooTraceEventHandler() {
    super();
    this.hooks.add(new TraceHook("sched_switch"));
  }

  public void handle_sched_switch(TraceReader reader,
                                  CtfTmfEvent event) {
    // Process event
  }
}

By convention, the function "handle_sched_switch" is called only with an instance of "sched_switch" event as argument. The magic happens by first getting a reference the method by it's name (done once), and then call it dynamically later in the processing path, similar to the following small example.

method = dummy.getClass().getMethod("foo", (Class[]) null);
...
method.invoke(dummy);

To compare dynamic invocation to compile-time method call, I did a trivial benchmark program. Here are the results for 10 billion calls.

StaticMethodBenchmark     9,653000
DynamicMethodBenchmark    47,625000

This experiment shows that dynamic invocation is roughly 5x slower than compile-time method call. Dynamic invocations is also weaker, because a missing method for the corresponding hook will be detected only at runtime.

There are benefits to using hooks. The test for the event type is done only once for all handlers. It avoid quite a lot of repetition. Also, it allows to list events required for a specific analysis, and then enable only this subset in the tracing session, reducing the runtime overhead and the trace size compared to enabling all events. So, we need to preserve these properties, but with compile-time invocations.

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!