内核性能调试–ftrace

调试难度本来就是写代码的两倍.因此,如果你写代码的时候聪明用尽,根据定义,你就没有能耐去调试它了.” – Brian Kernighan


某手机公司的研发总监谈到内核调试时问我怎么android手机上解决有时整机响应慢甚至无响应的情况。 我说可以首先使能内核的调试选项检查是否存在内核死锁，再通过内核的kprobe/ftrace检查中断和系统调用情况，blabla… 没想到该总说“我们公司几百号人都没有用trace，你能用得起来？”。难怪即使几百号人做手机，每个人还得被强制加班?


据说，linus等大神级内核开发者不用调试器，顶多用printk打印信息。 对于寻常百姓来说， 每改一行代码都希望能马上看到效果，一次次的编译内核，就像盲人摸象一样，这时printk就像烧火棍一样， 难堪重用，调试效率效率非常的低。ftrace是内核内置的跟踪器，可用于跟踪内核函数调用，中断延迟，调度延迟， 系统调用等，在debugfs下使用文本命令交互，很合适内核开发者使用。


使用 ftrace
首先使用CONFIG_DEBUG_FS，CONFIG_FTRACE_*选项后重新编译内核。需要注意的是， 由于这时编译器打开-pg选项，内核映像加入了大量的调试信息，内核运行速度会变慢。 所以正式发布的版本都应该关闭此选项。


# mount -t debugfs nodev /sys/kernel/debug
# cd /sys/kernel/debug/trace
该目录下包含很多文件，用于设定/过滤/查看等，如：


内核中断
查看当前系统的中断情况


# echo 0 > tracing_on
# echo > trace
# echo nop > current_tracer
# echo irq > set_event
# echo 1 > tracing_on
# cat trace_pipe
 tracer: nop
 entries-in-buffer/entries-written: 0/0   #P:1


                              _-----=> irqs-off
                             / _----=> need-resched
                            | / _---=> hardirq/softirq
                            || / _--=> preempt-depth
                            ||| /     delay
           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
              | |       |   ||||       |         |
cat-1449  [000] d.h.  3927.679420: irq_handler_entry: irq=4 name=serial
...
内核调用
查看内核函数的调用情况


# echo > set_event
# echo 0 > tracing_on
# echo > trace
# echo function_graph > current_tracer
# echo 1 > tracing_on
# cat trace_pipe


tracer: function_graph


CPU  DURATION                  FUNCTION CALLS
 |     |   |                     |   |   |   |
0) + 26.523 us   |                      }
0)               |            finish_task_switch() {
0)   ==========> |
0)               |              smp_apic_timer_interrupt() {
0)               |                irq_enter() {
0)   0.911 us    |                  rcu_irq_enter();
0)   6.503 us    |                }
0)               |                hrtimer_interrupt() {
0)   0.585 us    |                  _raw_spin_lock();
0)   1.124 us    |                  ktime_get_update_offsets();
CPU:0 [LOST 163499 EVENTS]
------------------------------------------
0)  kworker-691   =>    cat-1464   
------------------------------------------


0)               |                              serial8250_default_handle_irq() {
0)   0.954 us    |                                io_serial_in();
...
内核函数的profile
打印当前内核的函数profile


# echo > current_tracer
# echo 1 > function_profile_enabled
# cat trace_stat/function0 
Function                               Hit    Time            Avg             s^2
--------                               ---    ----            ---             ---
__schedule                            7113    968683296 us     136184.9 us     2108946573 us 
schedule                              1687    954817829 us     565985.6 us     1349415472 us 
sys_poll                                25    63786678 us     2551467 us     582022796 us 
do_sys_poll                             25    63786547 us     2551461 us     566803126 us 
poll_schedule_timeout                   25    63771744 us     2550869 us     1312623772 us 
schedule_hrtimeout_range                25    63771626 us     2550865 us     1305229109 us 
schedule_hrtimeout_range_clock          25    63771510 us     2550860 us     1293434582 us 
schedule_timeout                        29    34992964 us     1206653 us     1503283302 us 
...
上面仅列出ftrace的三种应用场景，其它更多的说明可见Documentation/trace/ftrace.txt。 通过ftrace可以实时的跟踪内核的运行情况，通过分析它的日志，一般能较快的找出内核的性能瓶颈。