使用Ftrace调试Linux内核

Posted on Edited on In

在进行内核调试时， 最长使用的方式就是printk()，由于printk()被设计成可以在任何上下文（进程上下文、中断上下文）执行，因此它会在执行过程中带来较大的开销，尤其是所调试的代码对时间很敏感时，比如时间中断。而ftrace则能够在输出log的同时，最大程度上降低调试带来的开销。

配置Ftrace

Ftrace的API接口位于DebugFS中，可以直接通过修改对应的文件来控制Ftrace，它们都位于

1
/sys/kernel/debug/tracing

如果没有该目录，首先检查DebugFS是否挂载，如果没有可以手动挂载

1
2
mount -v | grep debugfs
mount -t debugfs debugfs /sys/kernel/debug

然后检查相关的内核选项是否开启

1
2
3
4
CONFIG_FUNCTION_TRACER
CONFIG_FUNCTION_GRAPH_TRACER
CONFIG_STACK_TRACER
CONFIG_DYNAMIC_FTRACE

以下的操作都在该目录中进行。

启动/停止tracing

开启Ftrace后虽然不会影响系统的功能，但是会对性能造成一定的影响，而且用于记录log的buffer空间有限，如果不及时停止，关键的数据就会被新数据覆盖。

用户空间

1
2
3
4
# start tracing
echo 1 > tracing_on
# stop tracing
echo 0 > tracing_on

内核空间

1
2
3
4
/* start tracing */
tracing_on();
/* stop tracing*/
tracing_off();

Tracers

Ftrace提供了多种tracer，每种tracer都会以特定的格式记录PID、TIMESTAMP、FUNCTION等数据，同一时刻只能选择一种tracer。

查看当前内核所支持的tracer

1
cat available_tracers
1
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop

要启用对应的tracer，直接将其名称echo到current_tracer 中即可

1
echo function > current_tracer

通过trace文件可以直接读取抓取的log数据。

1
cat trace

下面介绍几种常用的tracer

function tracer

function tracer生成的log数据较为全面，但是对于函数的嵌套关系描述不是很直观。

抓取的log格式如下

1
2
3
4
5
6
7
8
9
10
11
12
# tracer: function
#
# entries-in-buffer/entries-written: 410007/21079612   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
             awk-8215  [006] d... 17018.301564: __mod_zone_page_state <-release_pages

第一函数是当前执行的函数，第二个是其调用者。

function_graph tracer

function_graph tracer很适合分析内核代码的执行路径，以及性能优化。

抓取的log格式如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 6)   0.546 us    |                  get_mem_cgroup_from_mm();
 6)               |                  memcg_kmem_charge_memcg() {
 6)   0.325 us    |                    try_charge();
 6)   0.331 us    |                    page_counter_try_charge();
 6)   1.551 us    |                  }
 6)   3.050 us    |                } /* memcg_kmem_charge */
 6)   7.527 us    |              } /* __alloc_pages_nodemask */
 6) + 10.066 us   |            } /* alloc_pages_current */
 6)   0.365 us    |            inc_zone_page_state();
 6) + 11.301 us   |          } /* pte_alloc_one */
 6)               |          filemap_map_pages() {
 6)               |            alloc_set_pte() {

通过DURATION这一列可以看出每个函数的执行时间。

如果超过10微秒，则在前面会有“**+**”

如果超过100微秒，则在前面会有“**!**”

添加自定义log

有时，内核自带的trace point可能无法满足我们需求，这时，我们可以添加额外的trace log，并让其与原本的log结合起来。

内核空间 —— trace_printk()

文章一开始就提到，虽然printk()使用起来简单，但是其开销较大，有时甚至会影响到我们对内核进行调试。

比如在调试scheduler或者network这种非常忙碌的子系统时，printk()会极大地拖慢系统性能，甚至造成死锁；而在调试一些竞态问题时，使用printk()甚至会让问题“消失”，或者难以复现。

而Ftrace提供的trace_printk()则可以用于这些调试场景，跟printk()一样，它也可以用于任何上下文中；不同的是，它不会把log输出到console，而是输出到一个独立的buffer。使用trace_printk()输出的log会与其它tracer输出的log结合。

在内核模块中测试trace_printk()，模块代码如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
#include <linux/kernel.h>
#include <linux/module.h>

MODULE_LICENSE("GPL");
MODULE_AUTHOR("colorfulshark@hotmail.com");

static int hello_kernel_init(void)
{
        tracing_on();
        trace_printk("hello kernel\n");
        return 0;
}

static void hello_kernel_exit(void)
{
        trace_printk("goodbye kenrel\n");
        tracing_off();
}

module_init(hello_kernel_init);
module_exit(hello_kernel_exit);

  • 当使用nop/function作为tracer时，输出的log如下

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    # tracer: nop
    #
    # entries-in-buffer/entries-written: 2/2   #P:8
    #
    #                              _-----=> irqs-off
    #                             / _----=> need-resched
    #                            | / _---=> hardirq/softirq
    #                            || / _--=> preempt-depth
    #                            ||| /     delay
    #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
    #              | |       |   ||||       |         |
              insmod-1442  [002] .... 23080.367994: 0xffffffffc044a005: hello kernel
               rmmod-4353  [003] .... 23271.094110: 0xffffffffc044a025: goodbye kenrel

  • 当使用function_graph作为tracer时，自定义的log会以类似注释的形式出现

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    # tracer: function_graph
    #
    # CPU  DURATION                  FUNCTION CALLS
    # |     |   |                     |   |   |   |
     5)               |  /* hello kernel */
     6)   1.430 us    |  _raw_spin_unlock_irqrestore();
     5)               |  blocking_notifier_call_chain() {
     5)               |    down_read() {
     5)               |      _cond_resched() {
     5)   0.195 us    |        rcu_all_qs();
     5)   0.627 us    |      }
     [...]
     2)               |      0xffffffffc044a030() {
     5)   0.235 us    |                  rcu_cblist_dequeue();
     2)               |        /* goodbye kenrel */

用户空间 —— trace_marker

在调试用户空间程序时，我们可能会希望能够同步了解内核里的状态，虽然Ftrace输出的log有时间戳，但它跟墙钟并没有非常精确的对应关系，所以最好的解决方法是让用户空间的程序有能力把log输出到Ftrace的buffer中，从而与tracer输出的log结合。使用trace_marker这个文件即可实现这个功能。

1
echo 'hello trace' > trace_marker

其效果与在内核空间使用的trace_printk()相同。

使用Ftrace调试oops

当内核崩溃时，我们通常只能获得崩溃发生时的上下文信息，但是对于崩溃之前发生的事却所知甚少，通过使用ftrace_dump_on_oops，即可在内核发生崩溃时，将Ftrace buffer中的内容打印到console上。这对于揭示崩溃发生的原因可能起到至关重要的作用。

1
echo 1 > ftrace_dump_on_oops

使用sysrq-z可以手动触发这个过程，也可以直接在内核代码中使用ftrace_dump()来触发。

使用Ftrace跟踪栈的使用

因为内核栈空间非常有限，分析内核函数对于栈空间的使用可以用于优化内核代码。

要使用这个功能，首先要启动相应的内核选项

1
CONFIG_STACK_TRACER

虽然这个tracer是基于function tracer开发的，但是它使用独立的buffer

1
echo 1 > /proc/sys/kernel/stack_tracer_enabled

如果需要从系统启动就开始记录栈的使用，将stacktrace加到内核的启动参数中即可。

  • 查看到目前为止被使用过的最大的栈

    1
    cat stack_max_size
    1
    2728

  • 查看每个函数使用的栈大小

    1
    cat stack_trace
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
          Depth    Size   Location    (15 entries)
          -----    ----   --------
    0)     2840      64   __msecs_to_jiffies+0x5/0x30
    1)     2776      80   update_group_capacity+0x28/0x1f0
    2)     2696     384   find_busiest_group+0xff/0x9c0
    3)     2312     248   load_balance+0x164/0x9d0
    4)     2064     112   pick_next_task_fair+0x443/0x5b0
    5)     1952     104   __schedule+0x11e/0x880
    6)     1848      16   schedule+0x2c/0x80
    7)     1832     144   schedule_hrtimeout_range_clock+0x181/0x190

总结

Ftrace非常强大，但是通过DebugFS使用起来也非常复杂，以后会介绍基于Ftrace API接口的工具，比如trace-cmd，kernelshark，它们可以大大简化Ftrace的使用。

参考资料

Debugging the kernel using Ftrace - part 1

Debugging the kernel using Ftrace - part 2

ftrace - Function Tracer