← Back to LTTng's blog

Announcing the release of LTTng 2.7

Jérémie Galarneau on 14 October 2015

Comments

We're happy to announce the release of LTTng 2.7 "Herbe à Détourne". Following on the coattails of a conservative 2.6 release, LTTng 2.7 introduces a number of long-requested features.

It is also our first release since we have started pouring considerable efforts into our Continuous Integration setup to test the complete toolchain on every build configuration and platform we support. We are not done yet, but we're getting there fast!

While we have always been diligent about robustness, we have, in the past, mostly relied on our users to report problems occurring on non-Intel platforms or under non-default build scenarios. Now, with this setup in place at EfficiOS, it has become very easy for us to ensure new features and fixes work reliably and can be deployed safely for most of our user base.

Testing tracers—especially kernel tracers—poses a number of interesting challenges which we'll cover in a follow-up post. For now, let's talk features!

Kernel filtering

While LTTng has supported filtering of user space events for a long time, LTTng 2.7 now makes it possible to attach a filter to a kernel event when it is first enabled.

Filters are specified by C-like expressions which are dynamically evaluated against events to reduce the amount of events being recorded to a trace. For instance, it is now possible to trace every invocation of the write() system call with a payload larger than 100 bytes.

This can be achieved by enabling the write() system call and providing a filter expression.

lttng enable-event --kernel --syscall write --filter "count > 100"

This is a handy tool to quickly reduce the amount of data to sift through when investigating a problem.

[15:02:28.557877153] (+0.003936173) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "ssh" }, { fd = 5, buf = 94097319473858, count = 4095 }
[15:02:28.558899341] (+0.001022188) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "ssh" }, { fd = 5, buf = 94097319468416, count = 3148 }
[15:02:31.323397195] (+2.764497854) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_IOThread" }, { fd = 146, buf = 15269810037264, count = 176 }
[15:02:31.323687516] (+0.000290321) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_IOThread" }, { fd = 146, buf = 15269790656752, count = 169 }
[15:02:31.325460834] (+0.001773318) XThink syscall_entry_write: { cpu_id = 0 }, { procname = "BrowserBlocking" }, { fd = 59, buf = 15269860282392, count = 520192 }
[15:02:31.325564719] (+0.000103885) XThink syscall_entry_write: { cpu_id = 0 }, { procname = "BrowserBlocking" }, { fd = 59, buf = 140309699067904, count = 3976 }
[15:02:31.333541760] (+0.007977041) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_FileThre" }, { fd = 292, buf = 15269789575704, count = 279 }
[15:02:31.334523566] (+0.000981806) XThink syscall_entry_write: { cpu_id = 3 }, { procname = "Chrome_FileThre" }, { fd = 292, buf = 15269789575704, count = 279 }
[15:02:31.335080492] (+0.000556926) XThink syscall_entry_write: { cpu_id = 3 }, { procname = "Chrome_FileThre" }, { fd = 292, buf = 15269789575704, count = 279 }
[15:02:31.342076188] (+0.006995696) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_IOThread" }, { fd = 124, buf = 15269798800512, count = 300 }
[15:02:31.414602941] (+0.072526753) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_IOThread" }, { fd = 124, buf = 15269821225824, count = 203 }
[15:02:31.414715714] (+0.000112773) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_IOThread" }, { fd = 124, buf = 15269807877216, count = 263 }
[15:02:31.427803794] (+0.013088080) XThink syscall_entry_write: { cpu_id = 0 }, { procname = "Chrome_IOThread" }, { fd = 124, buf = 15269818173632, count = 394 }
[15:02:31.917912677] (+0.400593753) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_HistoryT" }, { fd = 147, buf = 15269714267400, count = 512 }
[15:02:31.917931214] (+0.000018537) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_HistoryT" }, { fd = 61, buf = 15269741980936, count = 2048 }
[15:02:31.918080718] (+0.000149504) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_HistoryT" }, { fd = 181, buf = 15269720687112, count = 4096 }
[15:02:31.918105831] (+0.000025113) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_HistoryT" }, { fd = 181, buf = 15269782003720, count = 4096 }
[15:02:31.918118110] (+0.000012279) XThink syscall_entry_write: { cpu_id = 2 }, { procname = "Chrome_HistoryT" }, { fd = 181, buf = 15269791514632, count = 4096 }

Process (PID) tracker

Filter expressions are a great tool to significantly reduce the amount of events being traced on a given system. However, users have often let us know they wished they could only track a given process, as other tools—such as strace—do.

To this end, LTTng 2.7 introduces the notion of trackers, which are used to follow events associated to a given resource across multiple domains.

To track events associated with a given Process Identifier (PID), a PID tracker can be assigned to a tracing session. Such a tracker acts as a top-level filter which is applied to all events in a session's domain.

Let's run through a small example to track the handling of an HTTP request by Node.js across the kernel and Node.js itself.

$ lttng create node-demo
Session node-demo created.
Traces will be written in /home/jgalar/lttng-traces/node-demo-20151005-180235

$ pidof node
956

$ lttng track --kernel --pid 956
PID 956 tracked in session node-demo

$ lttng track --userspace --pid 956
PID 956 tracked in session node-demo

$ lttng enable-event --kernel --all
All Kernel events are enabled in channel channel0

$ lttng enable-event --userspace --all
All UST events are enabled in channel channel0

$ lttng start
[...]

After a while, we can stop the session and have a look at the resulting trace. First, we can see the kernel returning from the epoll(), which node uses to wait for a new connection.

[18:03:36.847046439] (+0.000007750) XThink syscall_exit_epoll_wait: { cpu_id = 3 }, { ret = 1, events = 140728832813824 }

node then performs a read() on the socket and emits the http_server_request event, signalling the start of its processing.

[18:03:36.847059675] (+0.000013236) XThink syscall_entry_read: { cpu_id = 3 }, { fd = 26, count = 65536 }
[18:03:36.847064285] (+0.000004610) XThink skb_copy_datagram_iovec: { cpu_id = 3 }, { skbaddr = 18446612148662969576, len = 310 }
[18:03:36.847068539] (+0.000004254) XThink syscall_exit_read: { cpu_id = 3 }, { ret = 310, buf = 49358448 }
[18:03:36.847144549] (+0.000076010) XThink kmem_mm_page_alloc: { cpu_id = 3 }, { page = 0xFFFFEA0000D0D940, order = 0, gfp_flags = 164058, migratetype = 2 }

[18:03:36.847326206] (+0.000181657) XThink node:http_server_request: { cpu_id = 3 }, { url = "/", method = "GET", forwardedFor = "" }

Since the Node.js instrumentation is still relatively terse, it is hard to have an idea of exactly what goes on during the processing of that request. However, we see that 32 page allocation events occur in kernel space before node writes the result of the request using the writev() system call.

[18:03:36.847402792] (+0.000076586) XThink kmem_mm_page_alloc_zone_locked: { cpu_id = 3 }, { page = 0xFFFFEA0000DA1800, order = 0, migratetype = 2 }
[18:03:36.847403846] (+0.000001054) XThink kmem_mm_page_alloc_zone_locked: { cpu_id = 3 }, { page = 0xFFFFEA0000DA1840, order = 0, migratetype = 2 }
[18:03:36.847404279] (+0.000000433) XThink kmem_mm_page_alloc_zone_locked: { cpu_id = 3 }, { page = 0xFFFFEA0000DA1880, order = 0, migratetype = 2 }
[18:03:36.847404652] (+0.000000373) XThink kmem_mm_page_alloc_zone_locked: { cpu_id = 3 }, { page = 0xFFFFEA0000DA18C0, order = 0, migratetype = 2 }
[18:03:36.847405132] (+0.000000480) XThink kmem_mm_page_alloc_zone_locked: { cpu_id = 3 }, { page = 0xFFFFEA0000DA1900, order = 0, migratetype = 2 }
[18:03:36.847405562] (+0.000000430) XThink kmem_mm_page_alloc_zone_locked: { cpu_id = 3 }, { page = 0xFFFFEA0000DA1940, order = 0, migratetype = 2 }
[18:03:36.847405962] (+0.000000400) XThink kmem_mm_page_alloc_zone_locked: { cpu_id = 3 }, { page = 0xFFFFEA0000DA1980, order = 0, migratetype = 2 }
[...]
[18:03:36.847416719] (+0.000001500) XThink kmem_mm_page_alloc: { cpu_id = 3 }, { page = 0xFFFFEA0000DA1800, order = 0, gfp_flags = 164058, migratetype = 2 }
[18:03:36.847509646] (+0.000092927) XThink syscall_entry_writev: { cpu_id = 3 }, { fd = 26, vec = 49184128, vlen = 2 }

We can then follow the path of this request in the network stack and see node return to a quiescent state, waiting for the next event on its connection socket.

[18:03:36.847516326] (+0.000006680) XThink kmem_cache_alloc_node: { cpu_id = 3 }, { call_site = 0xFFFFFFFF81460ACB, ptr = 0xFFFF8803CE762600, bytes_req = 512, bytes_alloc = 512, gfp_flags = 208, node = -1 }
[18:03:36.847517752] (+0.000001426) XThink kmem_kmalloc_node: { cpu_id = 3 }, { call_site = 0xFFFFFFFF81460AF7, ptr = 0xFFFF88043AFD3800, bytes_req = 2048, bytes_alloc = 2048, gfp_flags = 66256, node = -1 }
[18:03:36.847524762] (+0.000007010) XThink net_dev_queue: { cpu_id = 3 }, { skbaddr = 18446612148662970088, len = 222, name = "lo" }
[18:03:36.847527269] (+0.000002507) XThink net_if_rx: { cpu_id = 3 }, { skbaddr = 18446612148662970088, len = 208, name = "lo" }
[18:03:36.847528352] (+0.000001083) XThink irq_softirq_raise: { cpu_id = 3 }, { vec = 3 }
[18:03:36.847529186] (+0.000000834) XThink net_dev_xmit: { cpu_id = 3 }, { skbaddr = 18446612148662970088, rc = 0, len = 222, name = "lo" }
[18:03:36.847530379] (+0.000001193) XThink irq_softirq_entry: { cpu_id = 3 }, { vec = 3 }
[18:03:36.847531372] (+0.000000993) XThink net_if_receive_skb: { cpu_id = 3 }, { skbaddr = 18446612148662970088, len = 208, name = "lo" }
[18:03:36.847536179] (+0.000004807) XThink napi_poll: { cpu_id = 3 }, { napi = 18446612151359333392, dev_name = "(no_device)" }
[18:03:36.847536799] (+0.000000620) XThink irq_softirq_exit: { cpu_id = 3 }, { vec = 3 }
[18:03:36.847539112] (+0.000002313) XThink timer_start: { cpu_id = 3 }, { timer = 18446612134541520144, function = 18446744071583888432, expires = 4296212450, now = 4296212389, flags = 3 }
[18:03:36.847541446] (+0.000002334) XThink kmem_kfree: { cpu_id = 3 }, { call_site = 0xFFFFFFFF811D0DBF, ptr = 0x0 }
[18:03:36.847543466] (+0.000002020) XThink syscall_exit_writev: { cpu_id = 3 }, { ret = 156, vec = 49184128 }

[18:03:36.847595932] (+0.000052466) XThink node:http_server_response: { cpu_id = 3 }, { port = 58200, remote = "::ffff:127.0.0.1", fd = 26 }

[18:03:36.847678026] (+0.000082094) XThink kmem_mm_page_alloc: { cpu_id = 3 }, { page = 0xFFFFEA0000DA1840, order = 0, gfp_flags = 164058, migratetype = 2 }
[18:03:36.847734886] (+0.000056860) XThink syscall_entry_epoll_ctl: { cpu_id = 3 }, { epfd = 7, op = 3, fd = 26, event = 140728832813680 }

This demonstrates how trackers improve the signal-to-noise ratio of traces. Of course, this is only the start as we hope to make it even easier to hone-in on select components, processes or resources as we implement more trackers.

Kernel tracer wildcard support

Another feature we added, bringing the kernel tracer to parity with the user space tracer, is the addition of support for event name wildcards.

This little addition makes it possible to enable every event of a given kernel subsystem. For instance, enabling events matching power* will result in a trace containing all power management events.

$ lttng enable-event --kernel 'power*'

On Linux 4.2.2, this results in a trace containing the following events.

power_cpu_idle
power_cpu_frequency
power_machine_suspend
power_wakeup_source_activate
power_wakeup_source_deactivate
power_clock_enable
power_clock_disable
power_clock_set_rate
power_domain_target

Python logging support

Joining the ranks of java.util.logging and log4j, the Herbe à Détourne release adds support for the Python logging module for both Python 2.7 and 3.x.

In short, this means that importing the lttngust module makes it possible to funnel all Python logs through LTTng, automatically correlating them with events emitted by the kernel and other user space applications.

A complete guide to Python tracing has also been added to the official documentation.

File-backed user space buffers

This new LTTng-UST feature allows the mapping of ring buffers onto filesystems. This proves useful in combination with PRAMFS or DAX+pmem (Linux kernels 4.1+) to store tracer ring buffers in persistent memory upon an unexpected system reboot.

These buffers can be salvaged and converted to regular CTF traces using the newly introduced lttng-crash utility to see the events that led to a crash.

Support for custom clock sources and CPU identifier plugins

In the interest of keeping LTTng as unintrusive as possible, LTTng 2.7 introduces support for platform-specific plugins providing custom implementations of getcpu() and clock sources.

getcpu()/sched_getcpu() override plugins can prove useful in cases where direct access to architecture-specific registers provides a more efficient way of accessing the current CPU number than using the Linux's sched_getcpu() vDSO/system call.

A code sample demonstrating the implementation of such a plugin is available here.

Clock override plugins, which may be implemented as shared objects, useful in cases where direct access to architecture-specific clocks is available, and when they should be used in place of the Linux kernel monotonic clock.

We also have a code sample showing how to implement such a clock source here.

LTTng 2.8 will introduce support for custom kernel space clock sources. This feature is already available as part of LTTng-modules's master branch.

tracelog() instrumentation support

Multiple developers have made it clear that we needed to provide a quick and easy way to convert existing logging instrumentation to LTTng tracepoints.

To this end, we have introduced the tracelog() instrumentation facility with the goal of helping out C/C++ developers who wish to move away from existing text-based logging frameworks or need to accommodate multiple tracing backends.

tracelog() offers a very straightforward API. It accepts a log level, a format string and a variable number of arguments, not unlike printf().

Tracing text statements still has a number of drawbacks (runtime inefficiency, bloating the resulting trace, etc.). Nonetheless, tracelog() allows developers to take advantage of the complete LTTng feature set from the get-go.

Try it out!

We're very excited to have these new additions see the light of day. LTTng 2.7 "Herbe à Détourne" should be rolling out to your distributions soon. Until then, feel free to give it a try by building from source.

We wish to thank everyone who has contributed to this release!