使用Ftrace调试Linux内核

在进行内核调试时, 最长使用的方式就是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