Kernel tracing using lttng

LTTng (Linux Trace Toolkit - next generation) is a highly efficient system tracer that allows tracing of the kernel and userspace. It also provides tools to view and analyse the gathered trace data.  So let's see how to install and use LTTng kernel tracing in Ubuntu. First, one has to install the LTTng userspace tools:

 sudo apt-get update  
 sudo apt-get install lttng-tools babeltrace

LTTng was already recently added into the Ubuntu 13.10 Saucy kernel, however, with earlier releases one needs to install the LTTng kernel driver using lttng-modules-dkms as follows:

 sudo apt-get install lttng-modules-dkms  

It is a good idea to sanity check to see if the tools and driver are installed correctly, so first check to see the available kernel events on your machine:

 sudo lttng list -k  

And you should get a list similar to the following:

 Kernel events:  
 -------------  
    mm_vmscan_kswapd_sleep (loglevel: TRACE_EMERG (0)) (type: tracepoint)  
    mm_vmscan_kswapd_wake (loglevel: TRACE_EMERG (0)) (type: tracepoint)  
    mm_vmscan_wakeup_kswapd (loglevel: TRACE_EMERG (0)) (type: tracepoint)  
    mm_vmscan_direct_reclaim_begin (loglevel: TRACE_EMERG (0)) (type: tracepoint)  
    mm_vmscan_memcg_reclaim_begin (loglevel: TRACE_EMERG (0)) (type: tracepoint)  
 ..  

Next, we need to create a tracing session:

 sudo lttng create examplesession  

..and enable events to be traced using:

 sudo lttng enable-event sched_process_exec -k  

One can also specify multiple events as a comma separated list. Next, start the tracing using:

 sudo lttng start  

and to stop and complete the tracing use:

 sudo lttng stop  
 sudo lttng destroy  

and the trace data will be saved in the directory ~/lttng-traces/examplesession-[date]-[time]/.  One can examine the trace data using the babeltrace tool, for example:

 sudo babeltrace ~/lttng-traces/examplesession-20130517-125533  

And you should get a list similar to the following:

 [12:56:04.490960303] (+?.?????????) x220i sched_process_exec: { cpu_id = 2 }, { filename = "/usr/bin/firefox", tid = 4892, old_tid = 4892 }  
 [12:56:04.493116594] (+0.002156291) x220i sched_process_exec: { cpu_id = 0 }, { filename = "/usr/bin/which", tid = 4895, old_tid = 4895 }  
 [12:56:04.496291224] (+0.003174630) x220i sched_process_exec: { cpu_id = 2 }, { filename = "/usr/lib/firefox/firefox", tid = 4892, old_tid = 4892 }  
 [12:56:05.472770438] (+0.976479214) x220i sched_process_exec: { cpu_id = 2 }, { filename = "/usr/lib/libunity-webapps/unity-webapps-service", tid = 4910, old_tid = 4910 }  
 [12:56:05.478117340] (+0.005346902) x220i sched_process_exec: { cpu_id = 2 }, { filename = "/usr/bin/ubuntu-webapps-update-index", tid = 4912, old_tid = 4912 }  
 [12:56:10.834043409] (+5.355926069) x220i sched_process_exec: { cpu_id = 3 }, { filename = "/usr/bin/top", tid = 4937, old_tid = 4937 }  
 [12:56:13.668306764] (+2.834263355) x220i sched_process_exec: { cpu_id = 3 }, { filename = "/bin/ps", tid = 4938, old_tid = 4938 }  
 [12:56:16.047191671] (+2.378884907) x220i sched_process_exec: { cpu_id = 3 }, { filename = "/usr/bin/sudo", tid = 4939, old_tid = 4939 }  
 [12:56:16.059363974] (+0.012172303) x220i sched_process_exec: { cpu_id = 3 }, { filename = "/usr/bin/lttng", tid = 4940, old_tid = 4940 }  

The LTTng wiki contains many useful worked examples and is well worth exploring.

As it stands, LTTng is relatively light weight.   Research by Romik Guha Anjoy and Soumya Kanti Chakraborty shows that LTTng describes how the CPU overhead is ~1.6% on a Intel® CoreTM 2 Quad with four 64 bit Q9550 cores.  With measurements I've made with oprofile on a Nexus 4 with 1.5 GHz quad-core Snapdragon S4 Pro processor shows a CPU overhead of < 1% for kernel tracing.  In flight recorder mode, one can generate a lot of trace data. For example, with all tracing enabled running multiple stress tests I was able to generate ~850K second of trace data, so this will obviously impact disk I/O.

Getting started with oprofile on Ubuntu

Oprofile is a powerful system wide profiler for Linux.  It can profile all running code on a system with minimal overhead.   Running oprofile requires the uncompressed vmlinux image, so one has to also install the kernel .ddeb images.

To install oprofile:

 sudo apt-get update && sudo apt-get install oprofile

..and then install the kernel .ddebs:

 echo "deb http://ddebs.ubuntu.com $(lsb_release -cs) main restricted universe multiverse" | \  
 sudo tee -a /etc/apt/sources.list.d/ddebs.list  
 sudo apt-key adv --keyserver keyserver.ubuntu.com --recv-keys 428D7C01  
 sudo apt-get update  
 sudo apt-get install linux-image-$(uname -r)-dbgsym  

 ..the installed vmlinux image can be found in /usr/lib/debug/boot/vmlinux-$(uname-r)

Oprofile is now ready to be used.  Let's assume we want to profile the following command:

 dd if=/dev/urandom of=/dev/null bs=4K  

First, before running opcontrol, one may have to stop the NMI watchdog to free up counter 0 using the following:

 echo "0" | sudo tee /proc/sys/kernel/watchdog  

Next, we tell opcontrol the location of vmlinux, separate out kernel samples, initialize, reset profiling and start profiling:

 sudo opcontrol --vmlinux=/usr/lib/debug/boot/vmlinux-$(uname -r)  
 sudo opcontrol --separate=kernel  
 sudo opcontrol --init  
 sudo opcontrol --reset  
 sudo opcontrol --start  

 ..and run the command we want to profile for the desired duration. Next we stop profiling, generate a report for the executable we are interested in and de-initialize oprofile using:

 sudo opcontrol --stop  
 sudo opreport image:/bin/dd -gl  
 sudo opcontrol --deinit  

The resulting output from opreport is as follows:

 Using /var/lib/oprofile/samples/ for samples directory.  
 warning: /kvm could not be found.  
 CPU: Intel Ivy Bridge microarchitecture, speed 2.501e+06 MHz (estimated)  
 Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000  
 samples %    image name        symbol name  
 55868  59.8973 vmlinux-3.9.0-0-generic sha_transform  
 14942  16.0196 vmlinux-3.9.0-0-generic random_poll  
 10971  11.7622 vmlinux-3.9.0-0-generic ftrace_define_fields_random__mix_pool_bytes  
 3977   4.2638 vmlinux-3.9.0-0-generic extract_buf  
 1905   2.0424 vmlinux-3.9.0-0-generic __mix_pool_bytes  
 1596   1.7111 vmlinux-3.9.0-0-generic _mix_pool_bytes  
 900    0.9649 vmlinux-3.9.0-0-generic __ticket_spin_lock  
 737    0.7902 vmlinux-3.9.0-0-generic copy_user_enhanced_fast_string  
 574    0.6154 vmlinux-3.9.0-0-generic perf_trace_random__extract_entropy  
 419    0.4492 vmlinux-3.9.0-0-generic extract_entropy_user  
 336    0.3602 vmlinux-3.9.0-0-generic random_fasync  
 146    0.1565 vmlinux-3.9.0-0-generic sha_init  
 133    0.1426 vmlinux-3.9.0-0-generic wait_for_completion  
 129    0.1383 vmlinux-3.9.0-0-generic __ticket_spin_unlock  
 72     0.0772 vmlinux-3.9.0-0-generic default_spin_lock_flags  
 69     0.0740 vmlinux-3.9.0-0-generic _copy_to_user  
 35     0.0375 dd            /bin/dd  
 23     0.0247 vmlinux-3.9.0-0-generic __srcu_read_lock  
 22     0.0236 vmlinux-3.9.0-0-generic account  
 15     0.0161 vmlinux-3.9.0-0-generic fsnotify
...  

This example just scratches the surface of the capabilities of oprofile. For further reading I recommend reading the oprofile manual as it contains some excellent examples.