Linux Profiling Mechanisms

The last couple of years I have been writing under the Linux kernel and often see how people suffer from the ignorance of long-standing, generally accepted and (almost) convenient tools. For example, once we debugged the network at the next reincarnation of our device and tried to understand what kind of miracles happen with the processing of packets. Our first urge was to open the kernel sources and insert printk in the right places, collect logs, process them with some kind of python and then think for a long time. But no wonder I read lwn.net . I remembered that the kernel has ready-made and well-functioning mechanisms for tracing and profiling the kernel: those basic mechanisms with which you can collect some readings from the kernel, and then analyze them.



In the Linux kernel such mechanisms 3:

1. tracepoints
2. kprobes
3. perf events

Based on these 3 kernel features, absolutely all profilers and tracers are built that are available for Linux, including ftrace , perf , SystemTap , ktap and others. In this article I will tell you what they (mechanisms) give, how they work, and next time we will look at specific tools.

')

Kernel tracepoints

Kernel tracepoints is a kernel tracing framework, made through static code instrumentation. Yes, you understood correctly, most of the important functions of the kernel (network, memory management, scheduler) are statically instrumented. On my kernel, the number of tracepoints is:

  [etn] $ perf list tracepointt |  wc -l
   1271 

Among them are kmalloc:

  [etn] $ perf list tracepoint |  grep "kmalloc"
   kmem: kmalloc [Tracepoint event] 

And this is how it actually looks like in the nuclear function __do_kmalloc :

 /** * __do_kmalloc - allocate memory * @size: how many bytes of memory are required. * @flags: the type of memory to allocate (see kmalloc). * @caller: function caller for debug tracking of the caller */ static __always_inline void *__do_kmalloc(size_t size, gfp_t flags, unsigned long caller) { struct kmem_cache *cachep; void *ret; cachep = kmalloc_slab(size, flags); if (unlikely(ZERO_OR_NULL_PTR(cachep))) return cachep; ret = slab_alloc(cachep, flags, caller); trace_kmalloc(caller, ret, size, cachep->size, flags); return ret; } 

trace_kmalloc is tracepoint.



Such tracepoints write output to a debug ring buffer, which can be viewed in / sys / kernel / debug / tracing / trace:

  [~] # mount -t debugfs none / sys / kernel / debug
 [~] # cd / sys / kernel / debug / tracing /
 [tracing] # echo 1> events / kmem / kmalloc / enable 
 [tracing] # tail trace
 bash-10921 [000] .... 1127940.937139: kmalloc: call_site = ffffffff8122f0f5 ptr = ffff8800aaecb900 bytes_req = 48 bytes_alloc = 64 gfp_flags = GFP_KERNEL
 bash-10921 [000] .... 1127940.937139: kmalloc: call_site = ffffffff8122f084 ptr = ffff8800ca008800 bytes_req = 2048 bytes_alloc = 2048 gfp_flags = GFP_KERNEL | GFP_NOWARN | GFP_NORETRY
 bash-10921 [000] .... 1127940.937139: kmalloc: call_site = ffffffff8122f084 ptr = ffff8800aaecbd80 bytes_req = 64 bytes_alloc = 64 gfp_flags = GFP_KERNEL | GFP_NOWARN | GFP_NORETRY
 tail-11005 [001] .... 1127940.937451: kmalloc: call_site = ffffffff81219297 ptr = ffff8800aecf5f00 bytes_req = 240 bytes_alloc = 256 gfp_flags = GFP_KERNEL | GFP_ZERO
 tail-11005 [000] .... 1127940.937518: kmalloc: call_site = ffffffff81267801 ptr = ffff880123e8bd80 bytes_req = 128 bytes_alloc = 128 gfp_flags = GFP_KERNEL
 tail-11005 [000] .... 1127940.937519: kmalloc: call_site = ffffffff81267786 ptr = ffff880077faca00 bytes_req = 504 bytes_alloc = 512 gfp_flags = GFP_KERNEL 

Note that trasepoint “kmem: kmalloc”, like everyone else, is turned off by default, so you need to turn it on by saying 1 to its enable file.



You can write a tracepoint for your own kernel module. But, firstly , it is not so simple, because tracepoints are not the most convenient and understandable API : see examples in samples / trace_events / (in general, all these tracepoints are the black magic of C-macros , to understand which if you really want to, then not immediately succeed). And secondly , most likely, they will not work in your module, as long as you have CONFIG_MODULE_SIG enabled (almost always yes) and no private key for the signature (it is in the kernel vendor of your distribution). See heartbreaking details in lkml [1] , [2] .



In short, tracepoints are a simple and lightweight thing, but using it is inconvenient and not recommended - use ftrace or perf .

kprobes

If tracepoints are tags of static instrumentation, then kprobes is a mechanism for dynamic instrumentation of the code. With kprobes, you can interrupt the execution of a nuclear code anywhere , call your handler, do what you want in it and go back as if nothing had happened.



How this is done: you write your own kernel module in which you register a handler for a specific kernel symbol (read, function) or any address in general.



It works like this:

• We make our own kernel module, in which we write our handler.
• We register our handler at some address A, whether it is just an address or some function.
• The kprobe subsystem copies the instructions to the address, A, and replaces them with the CPU trap ( int 3 for x86).
• Now, when the execution of the code reaches address A, an exception is generated, by which the registers are saved, and control is passed to the exception handler, which eventually becomes kprobes .
• The kprobes subsystem looks at the address of the exception, finds who was registered at address A, and calls our handler.
• When our handler finishes, the registers are restored, the saved instructions are executed, and execution continues.

There are 3 types of kprobes in the core:

• kprobes is a “baseline” probe that allows you to interrupt any part of the core.
• jprobes - jump probe, is inserted only at the beginning of the function, but it gives a convenient mechanism for accessing the arguments of the interrupted function for our handler. It also does not work at the expense of trap'ov, but through setjmp/longjmp (hence the name), that is, more lightweight.
• kretprobes - return probe, is inserted before exiting the function and gives convenient access to the result of the function.

With kprobes, we can trace anything, including the code of third-party modules. Let's do this for our miscdevice driver. I want to know that someone is trying to write to my device, to know what indent and how many bytes.

In my miscdevice driver, the function looks like this:

  ssize_t etn_write (struct file * filp, const char __user * buf, 
           size_t count, loff_t * f_pos) 

I wrote a simple jprobe module that writes the number of bytes and offset to the kernel log.

  root @ etn: ~ # tail -F /var/log/kern.log
 Jan 1 00:00:42 etn kernel: [42.923717] ETN JPROBE: jprobe_init: 46: Planted jprobe at bf00f7a8, handler addr bf071000
 Jan 1 00:00:43 etn kernel: [43.194840] ETN JPROBE: trace_etn_write: 23: Writing 2 bytes at offset 4
 Jan 1 00:00:43 etn kernel: [43.201827] ETN JPROBE: trace_etn_write: 23: Writing 2 bytes at offset 4 

In short, the thing is powerful, but it is not very convenient to use: there is no access to local variables (only through the indent from ebp ), you need to write a kernel module, debug, load , etc. There are examples available in samples / kprobes . But why all this if there is a SystemTap?

Perf events

Immediately I will say that you should not confuse “perf events” and the perf program - you will be told about the program separately.



“Perf events” is the meter access interface in the PMU (Performance Monitoring Unit), which is part of the CPU. Thanks to these metrics, you can easily ask the core to show you how many misses in the L1 cache, no matter what your architecture, whether it is ARM or amd64. True, your processor should have support in the kernel :-) Relatively relevant information on this subject can be found here .



To access these counters, as well as a huge pile of other good, the perf program was written. With its help, you can see which iron events are available to us.











It can be seen that x86 will be richer for such things.



To access "perf events", a special system call perf_event_open was made, to which you send the event itself and the config, which describes what you want to do with this event. In response, you get a file descriptor from which you can read the data collected by perf on the event.



On top of this, perf provides many different features, such as grouping events, filtering, outputting to different formats, analyzing collected profiles, etc. Therefore, perf now shoves everything that is possible: from tracepoint to eBPF and to the point that all ftrace they want to make part of perf [3] [4] .



In short, “perf_events” is of little interest in itself, and perf itself deserves a separate article, so for the seed I will show a simple example.



We speak:

  root @ etn: ~ # perf timechart record apt-get update
 ...
 root @ etn: ~ # perf timechart -i perf.data -o timechart.svg 

And we get this miracle:

Perf timechart

Conclusion

Thus, knowing a little more about tracing and profiling in the kernel, you can make life much easier for yourself and your friends, especially if you learn how to use real tools like ftrace , perf and SystemTap , but more on that another time.

Read

• https://events.linuxfoundation.org/sites/events/files/slides/kernel_profiling_debugging_tools_0.pdf
• http://events.linuxfoundation.org/sites/events/files/lcjp13_zannoni.pdf
• tracepoints :
  • Documentation / trace / tracepoints.txt
  • http://lttng.org/files/thesis/desnoyers-dissertation- 2009-12-v27 .pdf
  • http://lwn.net/Articles/379903/
  • http://lwn.net/Articles/381064/
  • http://lwn.net/Articles/383362/
• kprobes :
  • Documentation / kprobes.txt
  • https://lwn.net/Articles/132196/
• perf_events :
  • http://web.eece.maine.edu/~vweaver/projects/perf_events/
  • https://lwn.net/Articles/441209/