Debugging the kernel using Ftrace

Posted 2022-10-22 X-Solomon-X

前言

“Ftrace是一个内置在Linux内核中追踪工具。许多Linux发行版已经在最新版本中启用了Ftrace的各种配置。Ftrace给Linux带来的好处之一是可以查看内核内部发生的事情，可以更好地找到导致崩溃的确切原因，帮助开发人员创建正确的解决方案。本文分为两个部分：第一部分，讨论如何设置Ftrace、使用函数和函数调用图追踪器、在内核中写入Ftrace缓冲区以及在监测到问题的时候停止追踪器的各种方法。第二部分，讨论用户空间如何与Ftrace交互、更快停止追踪器的方法、调试崩溃以及查找哪些内核函数占用了最大的堆栈区。”

Ftrace的内核配置选项

    CONFIG_FUNCTION_TRACER
    CONFIG_FUNCTION_GRAPH_TRACER
    CONFIG_STACK_TRACER
    CONFIG_DYNAMIC_FTRACE

Ftrace最强大的追踪器之一是function追踪器。它使用GCC的-pg选项将内核中的每个函数都调用一个特殊的函数“mcount()”。当配置了CONFIG_DYNAMIC_FTRACE的时候，系统启动的时候，调用“mcount()”函数会被转化为NOP空指令，以此保证系统以100%的性能运行。在编译过程中，记录了“mcount()”调用点（call site），该列表在系统启动的时候将这些调用点转化为NOP指令；在启用了function或者function graph追踪器，将该列表记录的所有调用点转化为追踪调用函数。此外，CONFIG_DYNAMIC_FTRACE提供了筛选应该追踪哪个函数的能力。

debugfs文件接口

系统配置了Ftrace的编译选项后，用户通过Ftrace提供debugfs文件系统接口展开工作，通常目录在"/sys/kernel/debug/tracing"（也可以手动挂载）。

[root@VM-centos ~]# cd /sys/kernel/debug/tracing

[root@VM-centos tracing]# ls
available_events            dyn_ftrace_total_info     kprobe_profile       saved_tgids         snapshot            trace_marker_raw     uprobe_events
available_filter_functions  enabled_functions         max_graph_depth      set_event           stack_max_size      trace_options        uprobe_profile
available_tracers           error_log                 options              set_event_pid       stack_trace         trace_pipe
buffer_percent              events                    per_cpu              set_ftrace_filter   stack_trace_filter  trace_stat
buffer_size_kb              free_buffer               printk_formats       set_ftrace_notrace  timestamp_mode      tracing_cpumask
buffer_total_size_kb        function_profile_enabled  README               set_ftrace_pid      trace               tracing_max_latency
current_tracer              instances                 saved_cmdlines       set_graph_function  trace_clock         tracing_on
dynamic_events              kprobe_events             saved_cmdlines_size  set_graph_notrace   trace_marker        tracing_thresh

查看可用追踪器

available_tracer文件可用查看系统当钱有哪些追踪器是可用的：

[root@VM-centos tracing]# cat available_tracers
blk function_graph wakeup_dl wakeup_rt wakeup function nop

[root@VM-centos tracing]# pwd
/sys/kernel/debug/tracing

[root@VM-centos tracing]# cat available_tracers
blk function_graph wakeup_dl wakeup_rt wakeup function nop

激活function追踪器

将需要激活的追踪器名称echo到current_tracer文件中，即可以激活此追踪器。

[root@VM-centos tracing]# echo function > current_tracer 

[root@VM-centos tracing]# cat current_tracer 
function

[root@VM-centos tracing]# cat trace | head -20
# tracer: function
#
# entries-in-buffer/entries-written: 409933/78187643   #P:8
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
           sleep-430870  [003] .... 128241.811737: lookup_fast <-walk_component
           sleep-430870  [003] .... 128241.811737: __d_lookup_rcu <-lookup_fast
           sleep-430870  [003] .... 128241.811737: __follow_mount_rcu.isra.53.part.54 <-lookup_fast
           sleep-430870  [003] .... 128241.811737: inode_permission <-link_path_walk.part.60
           sleep-430870  [003] .... 128241.811737: generic_permission <-inode_permission
           sleep-430870  [003] .... 128241.811737: walk_component <-link_path_walk.part.60

激活function graph追踪器

由 Frederic Weisbecker 创建的function graph追踪器可以追踪函数进入和退出，这使得追踪器能够被了解被调用函数的深度，function graph追踪器可以使人更容易追踪内核中的执行控制流。function graph追踪器劫持函数的返回地址，在函数退出时插入追踪回调函数。这会破坏 CPU 的分支预测并导致比函数追踪器更多的开销，最接近的真实时间开销只出现在叶子函数中。

[root@VM-centos tracing]# cat available_tracers 
blk function_graph wakeup_dl wakeup_rt wakeup function nop

[root@VM-centos tracing]# echo function_graph > current_tracer
 
[root@VM-centos tracing]# cat trace | head -50
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 1)   0.121 us    |                    __tlb_remove_page_size();
 1)   0.110 us    |                    vm_normal_page();
 1)   0.110 us    |                    mark_page_accessed();
 1)               |                    page_remove_rmap() 
 1)               |                      lock_page_memcg() 
 1)   0.110 us    |                        lock_page_memcg.part.42();
 1)   0.320 us    |                          //lock_page_memcg的执行时间
 1)   0.110 us    |                      PageHuge();
 1)               |                      unlock_page_memcg() 
 1)   0.110 us    |                        __unlock_page_memcg();
 1)   0.321 us    |                          //unlock_page_memcg的执行时间
 1)   1.182 us    |                          //page_remove_rmap的执行时间

使用trace_printk函数

printk()函数可以提供很好的调试日志功能，但往往存在以下问题：

• 在频繁调用的函数中插入prink打印日志，严重造成系统响应延迟，并且，系统启动一直往终端打印日志，导致开机缓慢。
• 调试的信息和其他子系统的日志夹杂在一起，不方便查看。
• 如果在调试诸如定时器中断、调度程序或者网络之类的大容量区域，printk()可能会导致系统陷入困境，甚至可能会创建实时锁。

Ftrace引入了一种新形式的printk()，称为trace_printk(),它可以像printk()一样使用，也可以用于任何上下文（中断控制程序、NMI程序和调度程序）。 trace_printk() 的优点在于它不会输出到终端，相反，它写入 Ftrace的环形缓冲区，并且可以通过trace文件读取。 使用 trace_printk() 写入环形缓冲区只需要大约十分之一微秒左右，但是使用printk()，尤其是在写入串行控制台时，每次写入可能需要几毫秒。 trace_printk() 的性能优势使得可以记录内核中最敏感的区域，而几乎没有影响。并且，在nop tracer的情况下也能在trace中看到输出，这样就不会被函数调用信息干扰到了。

例如，在内核子系统或者在内核子模块中插入trace_printk函数：

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

通过查看trace文件，可以看到追踪的日志信息。

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

trace_printk() 的输出出现在任何追踪器中，甚至是function和function graph追踪器。

    [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();

trace_printk的输出更像是function和function graph的输出注释。

开启和暂停追踪

有时，只是想追逐特定的代码路径，或者只是想追踪运行特定测试时发生的情况，文件tracing_on用于禁止向环形缓冲区记录数据：

    [tracing]# echo 0 > tracing_on

这将禁止Ftrace向环形缓冲区冲刷记录，但追踪器的其他所有调用仍然发生，仍然会产生大量的开销。如果需要重新启用环形缓冲区，只需要将“1”写入该文件。

    [tracing]# echo 1 > tracing_on

请注意，在数字和大于号“>”之间留一个空格非常重要。 否则，您可能正在将标准输入或输出写入该文件。

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

推荐使用追踪器的流程

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

第一行禁止环形缓冲区记录任何数据， 接下来启用function graph追踪器。 function graph追踪器的开销仍然存在，但不会将任何内容记录到追踪缓冲区中。 最后一行启用环形缓冲区，运行测试程序，然后禁用环形缓冲区。 这缩小了function graph追踪器冲刷到环形缓冲区的数据范围，仅包括追踪run_test程序的数据。

上述禁用环形缓冲区的方法可能不够快，距离run_test用户进程执行完成后到关闭环形缓冲区之间，内核可能还执行了其他内核函数路径，并且冲刷到了环形缓冲区中，可能会造成环形缓冲区溢出并且丢失相关数据。后面将讨论如何从用户程序中关闭环形缓冲区的方法。

用户空间写入Ftrace环形缓冲区的方法

为了帮助同步用户空间和内核空间中的操作，创建了 trace_marker 文件。它提供了一种从用户空间写入 Ftrace 环形缓冲区的方法。该标记随后将出现在trace文件中，以给出trace文件中特定事件发生的位置。

    [tracing]# echo hello world > trace_marker
    [tracing]# cat trace
    # tracer: nop
    #
    #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
    #              | |       |          |         |
               <...>-3718  [001]  5546.183420: 0: hello world

用户程序读写tracing_on和trace_marker文件的方法

如果用户程序出现了问题并且需要找到用户程序特定位置的内核部分发生了什么，可以在用户程序启动时，打开这些文件以准备好文件描述符：

    int trace_fd = -1;
    int marker_fd = -1;

    int main(int argc, char **argv)
    
	    char *debugfs;
	    char path[256];
	    [...]

	    debugfs = find_debugfs();
	    if (debugfs) 
		    strcpy(path, debugfs);  /* BEWARE buffer overflow */
		    strcat(path,"/tracing/tracing_on");
		    trace_fd = open(path, O_WRONLY);
		    if (trace_fd >= 0)
			    write(trace_fd, "1", 1);

		    strcpy(path, debugfs);
		    strcat(path,"/tracing/trace_marker");
		    marker_fd = open(path, O_WRONLY);

然后，在代码中的某个关键位置，可以放置标记以显示应用程序当前所在的位置：

    if (marker_fd >= 0)
	    write(marker_fd, "In critical area\\n", 17);

    if (critical_function() < 0) 
	    /* we failed! */
	    if (trace_fd >= 0)
		    write(trace_fd, "0", 1);
    

当检测到critical_function()函数执行出现问题时，立即将 ASCII 字符“0”写入 trace_fd 文件描述符将停止跟踪。只有在检测到问题时才需要禁用追踪器，以便追踪并记录导致错误的历史记录。如果用户程序中需要间隔跟踪，它可以将 ASCII“1”写入 trace_fd 再次启用跟踪。

可以再参考一下这个简单的示例，它使用了上述初始化过程（这个示例没有加错误检查），：

    req.tv_sec = 0;
    req.tv_nsec = 1000;
    write(marker_fd, "before nano\\n", 12);
    nanosleep(&req, NULL);
    write(marker_fd, "after nano\\n", 11);
    write(trace_fd, "0", 1);

输出结果如下，请注意，对 trace_marker文件的写入在function graph追踪器中显示为注释。

    [...]
     0)               |      __kmalloc() 
     0)   0.528 us    |        get_slab();
     0)   2.271 us    |      
     0)               |      /* before nano */
     0)               |      kfree() 
     0)   0.475 us    |        __phys_addr();
     0)   2.062 us    |      
     0)   0.608 us    |      inotify_inode_queue_event();
     0)   0.485 us    |      __fsnotify_parent();
    [...]
     1)   0.523 us    |          _spin_unlock();
     0)   0.495 us    |    current_kernel_time();
     1)               |          it_real_fn() 
     0)   1.602 us    |  
     1)   0.728 us    |            __rcu_read_lock();
     0)               |  sys_nanosleep() 
     0)               |    hrtimer_nanosleep() 
     0)   0.526 us    |      hrtimer_init();
     1)   0.418 us    |            __rcu_read_lock();
     0)               |      do_nanosleep() 
     1)   1.114 us    |            _spin_lock_irqsave();
    [...]
     0)               |      __kmalloc() 
     1)   2.760 us    |  
     0)   0.556 us    |        get_slab();
     1)               |  mwait_idle() 
     0)   1.851 us    |      
     0)               |      /* after nano */
     0)               |      kfree() 
     0)   0.486 us    |        __phys_addr();

输出结果的第一列代表CPU核的编号。 当这样交错 CPU 追踪时，可能很难读取追踪。 工具 grep 可以很容易地过滤它，或者可以使用 per_cpu的trace文件：

    [tracing]# ls /sys/kernel/tracing/per_cpu
    cpu0  cpu1  cpu2  cpu3  cpu4  cpu5  cpu6  cpu7

在这些 CPU 目录中的每一个目录中都存在一个trace文件，仅显示该CPU的追踪。要在不受其他 CPU干扰的情况下更好地了解function graph追踪器的记录，只需查看 per_cpu/cpu0/trace。

    [tracing]# cat per_cpu/cpu0/trace
     0)               |      __kmalloc() 
     0)   0.528 us    |        get_slab();
     0)   2.271 us    |      
     0)               |      /* before nano */
     0)               |      kfree() 
     0)   0.475 us    |        __phys_addr();
     0)   2.062 us    |      
     0)   0.608 us    |      inotify_inode_queue_event();
     0)   0.485 us    |      __fsnotify_parent();
     0)   0.488 us    |      inotify_dentry_parent_queue_event();
     0)   1.106 us    |      fsnotify();
    [...]
     0)   0.721 us    |    _spin_unlock_irqrestore();
     0)   3.380 us    |  
     0)               |  audit_syscall_entry() 
     0)   0.495 us    |    current_kernel_time();
     0)   1.602 us    |  
     0)               |  sys_nanosleep() 
     0)               |    hrtimer_nanosleep() 
     0)   0.526 us    |      hrtimer_init();
     0)               |      do_nanosleep() 
     0)               |        hrtimer_start_range_ns() 
     0)               |          __hrtimer_start_range_ns() 
     0)               |            lock_hrtimer_base() 
     0)   0.866 us    |              _spin_lock_irqsave();
    [...]
     0)               |      __kmalloc() 
     0)               |        get_slab() 
     0)   1.851 us    |      
     0)               |      /* after nano */
     0)               |      kfree() 
     0)   0.486 us    |        __phys_addr();

在内核驱动程序的开发过程中，可能会存在测试程序出现奇怪错误的问题。 也许驱动程序陷入睡眠状态，永远不会醒来。当内核事件发生时，试图从用户空间禁用追踪器是很困难的，通常会导致环形缓冲区溢出和相关信息丢失，然后用户才能停止追踪。

内核中有两个运行良好的函数：tracing_on() 和tracing_off()。 这两个函数就像分别将“1”或“0”echo到tracing_on文件中一样。 如果内核中存在可以检查的某些条件，则可以通过添加如下内容来停止追踪器：

    if (test_for_error())
	    tracing_off();

接下来，添加几个 trace_printk()，重新编译并引导内核。 然后，可以启用function或function graph追踪器，然后等待错误条件发生。 检查tracing_on 文件将让您知道错误条件何时发生。 当内核调用tracing_off() 时，它将从“1”切换到“0”。 检查跟踪后，或将其保存在另一个文件中：

cat trace > ~/trace.sav

可以继续追踪以检查另一个命中。 为此，只需在tracing_on 中echo“1”，追踪将继续。

ftrace_dump_on_oops

有时内核会崩溃，将 kdump/kexec 与崩溃实用程序一起使用是检查崩溃点系统状态的一种有价值的方法，但它看不到在导致崩溃的事件之前发生了什么。 在内核引导参数中配置 Ftrace 并启用 ftrace_dump_on_oops，或者通过在 /proc/sys/kernel/ftrace_dump_on_oops 中echo“1”，将使 Ftrace 在 oops 或 panic 时以 ASCII 格式将整个追踪的环形缓冲区转储到控制台。将控制台输出到串行日志使调试崩溃更容易，现在可以追溯导致崩溃的事件。

转储到控制台可能需要很长时间，因为默认的 Ftrace 环形缓冲区每个 CPU 超过 1 兆字节。要缩小环形缓冲区的大小，请将希望环形缓冲区的千字节数写入 buffer_size_kb。请注意，该值是每个 CPU，而不是环形缓冲区的总大小。

    [tracing]# echo 50 > buffer_size_kb

以上将把 Ftrace 环形缓冲区缩小到每个 CPU 50 KB。 还可以使用 sysrq-z 将 Ftrace 缓冲区转储到控制台。 要为内核转储选择特定位置，内核可以直接调用 ftrace_dump()。 请注意，这可能会永久禁用 Ftrace，可能需要重新启动才能再次启用它。 这是因为 ftrace_dump() 读取环形缓冲区。 环形缓冲区被写入所有上下文（中断、NMI、调度），但环形缓冲区的读取需要锁定。 为了能够执行 ftrace_dump() 锁定被禁用并且缓冲区可能最终在输出后被破坏。

    /*
     * The following code will lock up the box, so we dump out the
     * trace before we hit that location.
     */
    ftrace_dump();

    /* code that locks up */

stack追踪器

最后要讨论的主题是检查内核堆栈大小以及每个函数使用多少堆栈空间的能力。 启用stack追踪器 (CONFIG_STACK_TRACER) 将显示堆栈使用最多的地方。 

stack追踪器是从function追踪器作为基础架构构建的。 它不使用 Ftrace 环形缓冲区，但确实使用function追踪器来插桩每个函数调用。因为它使用function追踪器作为基础架构，所以在未启用时不会增加开销。 要启用堆栈跟踪器，请将“1”echo到 /proc/sys/kernel/ stack_tracer_enabled。 要在启动期间查看最大堆栈的大小，请将“stacktrace”添加到内核启动参数。

stack跟踪器在每次函数调用时检查堆栈的大小，如果它大于最后记录的最大值，它会记录到stack trace中并使用新大小更新最大值。要查看当前最大值，请查看 stack_max_size 文件。

    [tracing]# echo 1 > /proc/sys/kernel/stack_tracer_enabled
    [tracing]# cat stack_max_size
    2928
    [tracing]# cat stack_trace
            Depth    Size   Location    (34 entries)
            -----    ----   --------
      0)     2952      16   mempool_alloc_slab+0x15/0x17
      1)     2936     144   mempool_alloc+0x52/0x104
      2)     2792      16   scsi_sg_alloc+0x4a/0x4c [scsi_mod]
      3)     2776     112   __sg_alloc_table+0x62/0x103
    [...]
     13)     2072      48   __elv_add_request+0x98/0x9f
     14)     2024     112   __make_request+0x43e/0x4bb
     15)     1912     224   generic_make_request+0x424/0x471
     16)     1688      80   submit_bio+0x108/0x115
     17)     1608      48   submit_bh+0xfc/0x11e
     18)     1560     112   __block_write_full_page+0x1ee/0x2e8
     19)     1448      80   block_write_full_page_endio+0xff/0x10e
     20)     1368      16   block_write_full_page+0x15/0x17
     21)     1352      16   blkdev_writepage+0x18/0x1a
     22)     1336      32   __writepage+0x1a/0x40
     23)     1304     304   write_cache_pages+0x241/0x3c1
     24)     1000      16   generic_writepages+0x27/0x29
    [...]
     30)      424      64   bdi_writeback_task+0x3f/0xb0
     31)      360      48   bdi_start_fn+0x76/0xd7
     32)      312     128   kthread+0x7f/0x87
     33)      184     184   child_rip+0xa/0x20

这不仅为您提供了找到的最大堆栈的大小，还显示了每个函数使用的堆栈大小的细分。请注意，write_cache_pages 的堆栈最大，使用了 304 个字节，其次是 generic_make_request，使用了 224 个字节的堆栈。 要重置最大值，请将“0”echo到 stack_max_size 文件中。

    [tracing]# echo 0 > stack_max_size

保持运行一段时间将显示内核使用过多堆栈的位置。但请记住，stack追踪器只有在未启用时才没有开销。当它运行时，性能会有所下降。

请注意，当内核使用单独的堆栈时，stack追踪器不会跟踪最大堆栈的大小。因为中断有自己的堆栈，它不会跟踪那里的堆栈使用情况。原因是当堆栈不是当前任务的堆栈时，目前没有简单的方法可以快速查看堆栈的顶部是什么。使用拆分堆栈时，进程堆栈可能是两页，而中断堆栈可能只有一页。这可能会在未来修复，但在使用stack追踪器时请记住这一点。

总结

Ftrace 是一个非常强大的工具，并且易于配置，不需要额外的工具。 本教程中显示的所有内容都可以在仅安装了 Busybox 的嵌入式设备上使用。 利用 Ftrace 基础设施应该可以减少调试难以发现的竞争条件所需的时间。 大胆地向printk()说再见吧，因为将function和function graph追踪器与trace_printk() 和tracing_off() 一起使用完全可以成为调试Linux 内核的主要工具。

参考目录

Debugging the kernel using Ftrace - part 1 [LWN.net]https://lwn.net/Articles/365835/Debugging the kernel using Ftrace - part 2 [LWN.net]https://lwn.net/Articles/366796/Secrets of the Ftrace function tracer [LWN.net]https://lwn.net/Articles/370423/linux/ftrace.rst at master · torvalds/linux · GitHubLinux kernel source tree. Contribute to torvalds/linux development by creating an account on GitHub.https://github.com/torvalds/linux/blob/master/Documentation/trace/ftrace.rst