Debugging the kernel using ftrace-Part 1

From: http://lwn.net/Articles/365835/

 

Ftrace is a great kernel debug tool. ftrace has more powerful debug functions than printk or other message printing methods. Others do not mention that because the execution time of printk is millisecond-level, the addition of printk will cause some bugs that are released to be difficult to reproduce. Ftrace uses ringbuffer, so the time is in microseconds, which is already a very obvious advantage. The trace can also be dumped when the kernel panic/Oops is used. See the following for details. There are three parts in total.

 

Ftrace is a tracing utility built directly into the Linux kernel. specified distributions already have varous deployments of ftrace enabled in their most recent releases. one of the benefits that ftrace brings to Linux is the ability to see what is happening inside the kernel. as such, this makes finding problem areas or simply tracking down that strange bug more manageable.

Ftrace's ability to show the events that lead up to a crash gives a better chance of finding exactly what caused it and can help the developer in creating the correct solution. this article is a two part series that will cover various methods of using ftrace for debugging the Linux kernel. this first part will talk briefly about setting up ftrace, using the function tracer, writing to the ftrace buffer from within the kernel, and varous ways to stop the tracer when a problem is detected.

Ftrace was derived from two tools. one was the "latency tracer" by Ingo Molnar used in the-RT tree. the other was my own "logdev" utility that had its primary use on debugging the Linux kernel. this article will mostly describe features that came out of logdev, but will also look at the function tracer that originated in the latency tracer.

Setting up ftrace

Currently the API to interface with ftrace is located in the debugfs file system. Typically, that is mounted/Sys/kernel/debug. For easier accessibility, I usually create/DebugDirectory and mount it there. Feel free to choose your own location for debugfs.

When ftrace is configured, it will create its own directory calledTracingWithin the debugfs file system. this article will reference those files in that directory as though the user first changed directory to the debugfs tracing directory to avoid any confusion as to where the debugfs file system has been mounted.

    [~]# cd /sys/kernel/debug/tracing    [tracing]#

This article is focusing on using ftrace as a debugging tool. some invocations for ftrace are used for other purposes, like finding latency or analyzing the system. for the purpose of debugging, The Kernel configuration parameters that shoshould be enabled are:

    CONFIG_FUNCTION_TRACER    CONFIG_FUNCTION_GRAPH_TRACER    CONFIG_STACK_TRACER    CONFIG_DYNAMIC_FTRACE

Function tracing-no modification necessary

One of the most powerful tracers of ftrace is the function tracer. It uses-PGOptionGccTo have every function in the kernel call a special function"Mcount ()". That function must be implemented in Assembly because the call does not follow the normal c Abi.

When config_dynamic_ftrace is configured the call is converted to a NOP at boot time to keep the system running at 100% performance. during compilation the mcount () call-sites are recorded. that list is used at boot time to convert those sites to NOPs. since NOPs are pretty useless for tracing, the list is saved to convert the call-sites back into trace callwhen the function (or function graph) tracer is enabled.

It is highly recommended to enable config_dynamic_ftrace because of this performance enhancement. in addition, config_dynamic_ftrace gives the ability to filter which function shocould be traced. note, even though the NOPs do not show any impact in benchmarks, the addition of frame pointers that come with-PGOption has been known to cause a slight overhead.

To find out which tracers are available, simply catAvailable_tracersFile inTracingDirectory:

    [tracing]# cat available_tracers     function_graph function sched_switch nop

To enable the function tracer, just echo "function" intoCurrent_tracerFile.

    [tracing]# echo function > current_tracer    [tracing]# cat current_tracer    function    [tracing]# cat trace | head -10    # tracer: function    #    #           TASK-PID    CPU#    TIMESTAMP  FUNCTION    #              | |       |          |         |                bash-16939 [000]  6075.461561: mutex_unlock <-tracing_set_tracer              <idle>-0     [001]  6075.461561: _spin_unlock_irqrestore <-hrtimer_get_next_event              <idle>-0     [001]  6075.461562: rcu_needs_cpu <-tick_nohz_stop_sched_tick                bash-16939 [000]  6075.461563: inotify_inode_queue_event <-vfs_write              <idle>-0     [001]  6075.461563: mwait_idle <-cpu_idle                bash-16939 [000]  6075.461563: __fsnotify_parent <-vfs_write

The header explains the format of the output pretty well. the first two items are the traced Task Name and PID. the CPU that the trace was executed on is within the brackets. the timestamp is the time since boot, followed by the function name. the function in this case is the function being traced with its parent following"<-"Symbol.

This information is quite powerful and shows the flow of functions nicely. but it can be a bit hard to follow. the function graph tracer, created by Frederic weisbecker, traces both the entry and exit of a function, which gives the tracer the ability to know the depth of functions that are called. the function graph tracer can make following the flow of execution within the kernel much easier to follow with the human eye:

    [tracing]# echo function_graph > current_tracer     [tracing]# cat trace | head -20    # tracer: function_graph    #    # CPU  DURATION                  FUNCTION CALLS    # |     |   |                     |   |   |   |     1)   1.015 us    |        _spin_lock_irqsave();     1)   0.476 us    |        internal_add_timer();     1)   0.423 us    |        wake_up_idle_cpu();     1)   0.461 us    |        _spin_unlock_irqrestore();     1)   4.770 us    |      }     1)   5.725 us    |    }     1)   0.450 us    |    mutex_unlock();     1) + 24.243 us   |  }     1)   0.483 us    |  _spin_lock_irq();     1)   0.517 us    |  _spin_unlock_irq();     1)               |  prepare_to_wait() {     1)   0.468 us    |    _spin_lock_irqsave();     1)   0.502 us    |    _spin_unlock_irqrestore();     1)   2.411 us    |  }     1)   0.449 us    |  kthread_should_stop();     1)               |  schedule() {

This gives the start and end of a function denoted with the C like annotation"{"To start a function and"}"At the end. Leaf functions, which do not call other functions, simply end with";". The duration column shows the time spent in the corresponding function. the function graph Tracer Records the time the function was entered and exited and reports the difference as the duration. these numbers only appear with the leaf functions and"}"Symbol. note that this time also has des the overhead of all functions within a nested function as well as the overhead of the function graph tracer itself. the function graph tracer hijacks the return address of the function in order to insert a trace callback for the function exit. this breaks the CPU's branch prediction and causes a bit more overhead than the function tracer. the closest true timings only occur for the leaf functions.

The lonely"+"That is there is an annotation marker. When the duration is greater than 10 microseconds,"+"Is shown. If the duration is greater than 100 microseconds"!"Will be displayed.

Using Trace_printk ()

Printk ()Is the king of all debuggers, but it has a problem. If you are debugging a high volume area such as the timer interrupt, The schedume, or the network,Printk ()Can lead to bogging down the system or can even create a live lock. It is also quite common to see a bug "disappear" when adding a fewPrintk ()S. This is due to the sheer overhead thatPrintk ()Introduces.

Ftrace introduces a new formPrintk ()CalledTrace_printk (). It can be used just likePrintk (), And can also be used in any context (Interrupt code, NMI code, and scheduler Code). What is nice aboutTrace_printk ()Is that it does not output to the console. Instead it writes to the ftrace ring buffer and can be read viaTraceFile.

Writing into the ring bufferTrace_printk ()Only takes around a tenth of a microsecond or so. But usingPrintk (), Especially when writing to the serial console, may take several milliseconds per write. The performance advantageTrace_printk ()Lets you record the most sensitive areas of the kernel with very little impact.

For example you can add something like this to the kernel or module:

    trace_printk("read foo %d out of bar %p\n", bar->foo, bar);

Then by looking atTraceFile, you can see your output.

    [tracing]# cat trace    # tracer: nop    #    #           TASK-PID    CPU#    TIMESTAMP  FUNCTION    #              | |       |          |         |               <...>-10690 [003] 17279.332920: : read foo 10 out of bar ffff880013a5bef8

The above example was done by adding a module that actually hadFooAndBarConstruct.

Trace_printk ()Output will appear in any tracer, even the function and function graph tracers.

    [tracing]# echo function_graph > current_tracer    [tracing]# insmod ~/modules/foo.ko    [tracing]# cat trace    # tracer: function_graph    #    # CPU  DURATION                  FUNCTION CALLS    # |     |   |                     |   |   |   |     3) + 16.283 us   |      }     3) + 17.364 us   |    }     3)               |    do_one_initcall() {     3)               |      /* read foo 10 out of bar ffff88001191bef8 */     3)   4.221 us    |    }     3)               |    __wake_up() {     3)   0.633 us    |      _spin_lock_irqsave();     3)   0.538 us    |      __wake_up_common();     3)   0.563 us    |      _spin_unlock_irqrestore();

Yes,Trace_printk ()Output looks like a comment in the function graph tracer.

Starting and stopping the trace

Obviously there are times where you only want to trace a particle code path. Perhaps you only want to trace what is happening when you run a specific test. The fileTracing_onIs used to disable the ring buffer from recording data:

    [tracing]# echo 0 > tracing_on

This will disable the ftrace ring buffer from recording. everything else still happens with the tracers and they will still incur most of their overhead. they do notice that the ring buffer is not recording and will not attempt to write any data, but the cballs that the tracers make are still med.

To re-enable the ring buffer, simply write a '1' into that file:

    [tracing]# echo 1 > tracing_on

Note, it is very important that you have a space between the number and the greater than sign">". Otherwise you may be writing standard input or output into that file.

    [tracing]# echo 0> tracing_on   /* this will not work! */

A common run might be:

    [tracing]# echo 0 > tracing_on    [tracing]# echo function_graph > current_tracer    [tracing]# echo 1 > tracing_on; run_test; echo 0 > tracing_on

The first line disables the ring buffer from recording any data. the next enables the function graph tracer. the overhead of the function graph tracer is still present but nothing will be recorded into the trace buffer. the last line enables the ring buffer, runs the test program, then disables the ring buffer. this narrows the data stored by the function graph tracer to include mostly just the data accumulated byRun_testProgram.

What's next?

The next article will continue the discussion on debugging the kernel with ftrace. The method above to disable the tracing may not be fast enough. The latency between the end of the programRun_testAnd echoing the 0 intoTracing_onFile may cause the ring buffer to overflow and lose the relevant data. I will discuss other methods to stop tracing a bit more efficiently, how to debug a crash, and looking at what functions in the kernel are Stack hogs. the best way to find out more is to enable ftrace and just play with it. you can learn a lot about how the kernel works by just following the function graph tracer.