Gather trace events in linux kernel
In this short post, we will learn how to use the ftrace tracing framework to gather the events generated in the linux kernel. These events can be very helpful when trying to troubleshoot a kernel bug.
Enabling ftrace
In order to be able to use ftrace, we need to enable it in the kernel’s .config file. We can do it by adding the following lines to the config file
CONFIG_FUNCTION_TRACER=y
CONFIG_FUNCTION_GRAPH_TRACER=y
CONFIG_STACK_TRACER=y
CONFIG_DYNAMIC_FTRACE=y
Configure the tracing options
Ftrace supports gathering traces via multiple tracers - the available tracers can be listed as follows:
$ cd /sys/kernel/debug/tracing/
$ cat available_tracers
blk function_graph function nop
Select the tracer which can be useful for the issue at hand, and set it as current tracer.
echo function_graph > current_tracer
Next, we have to set the events that have to be captured. This is easy enough as we can use pattern matching to get all the needed events. For example, to trace the functions defined for the block layer, we can trace them as follows:
echo "*blk*" > set_ftrace_filter
The above will get all the function names containing the word “blk” and put it in the file set_ftrace_filter.
Capturing the trace events
Now the events will be captured in the tracing buffer. We need to read from there as follows:
# 1. Read the trace file
cat trace
# 2. Stream from trace_pipe file
cat trace_pipe | tee traced_events.txts
With the second option above, we can get the events traced in a text file as output. Now to read the ftrace events, we can just read the text file or we can use a graphical tool such as kernelshark.
Sample output from my machine
root@syzkaller:/sys/kernel/debug/tracing# cat trace_pipe | less
1) 9.588 us | blk_mq_put_tag();
1) 5.831 us | blk_mq_put_tag();
1) | __blk_mq_sched_restart() {
1) | blk_mq_run_hw_queue() {
1) 6.442 us | blk_mq_hctx_has_pending();
1) + 18.635 us | }
1) + 29.836 us | }
1) 6.923 us | blk_queue_exit();
1) + 86.432 us | } /* __blk_mq_free_request */
1) ! 103.424 us | } /* blk_mq_free_request */
------------------------------------------
1) kworker-6382 => jbd2/sd-2889
------------------------------------------
1) + 18.315 us | blk_start_plug();
1) + 63.269 us | __getblk_gfp();
1) | bio_associate_blkg() {
1) + 11.832 us | kthread_blkcg();
1) + 12.433 us | blkcg_css.part.0();
1) + 32.811 us | bio_associate_blkg_from_css();
1) ! 112.882 us | }
1) + 13.295 us | blk_cgroup_bio_start();
1) | blk_mq_submit_bio() {
This gathered trace can now be used to understand the flow of the code and debug bugs.