通过trace-cmd和kernelshark简化Ftrace的使用

Posted on Edited on In

虽然Ftrace在debugfs中的接口很简单，但在实际操作时，还是显得不太灵活。如果能让一个应用程序代替我们与Ftrace的接口交互，将会大大简化其使用，而这个程序就是trace-cmd。此外，为了能够更加直观的分析过滤Ftrace的log，将会介绍一个基于GUI的工具kernelshark。

安装

从软件源安装

1
sudo apt install trace-cmd kernelshark

从源码安装

  1. 安装依赖

    1
    2
    3
    4
    sudo apt-get install build-essential git cmake libjson-c-dev -y
    sudo apt-get install freeglut3-dev libxmu-dev libxi-dev -y
    sudo apt-get install qtbase5-dev -y
    sudo apt-get install graphviz doxygen-gui -y

  2. 克隆源码

    1
    git clone https://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

  3. 编译安装

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    cd trace-cmd
    # compile trace-cmd
    make
    # install trace-cmd
    make install

    # compile kernelshark
    make gui
    # install kernelshark
    make install_gui

工作原理

下面是一个简单的例子:

1
2
sudo trace-cmd record -e ext4 ls
sudo trace-cmd report
1
2
3
4
5
6
7
8
9
10
11
12
CPU 0 is empty
CPU 1 is empty
CPU 2 is empty
CPU 3 is empty
CPU 4 is empty
CPU 6 is empty
CPU 7 is empty
cpus=8
              ls-8018  [005] 1233847.755818: ext4_es_lookup_extent_enter: dev 252,1 ino 28442625 lblk 0
              ls-8018  [005] 1233847.755834: ext4_es_lookup_extent_exit: dev 252,1 ino 28442625 found 1 [0/1) 113778720 W
              ls-8018  [005] 1233847.755859: ext4_journal_start:   dev 252,1 blocks, 2 rsv_blocks, 0 caller ext4_dirty_inode
              ls-8018  [005] 1233847.755861: ext4_mark_inode_dirty: dev 252,1 ino 28442625 caller ext4_dirty_inode

第一条命令记录了ls命令在执行时，ext4子系统中所有tracepoint的输出。输出结果保存在文件trace.dat中，可以分别对record和report使用-o和-i来设置输出和输入的文件名。

第二条命令解析trace.dat中的内容并打印到标准输出。可以看到CPU的数量以及哪些CPU的buffer为空，最下面则是记录的log，其格式与function tracer相同。

当开始记录时，trace-cmd会为每一个CPU创建一个进程，每个进程打开对应CPU的buffer文件并记录到单独的文件中，比如CPU0的buffer映射到/sys/kernel/debug/tracing/per_cpu/cpu0/trace_pipe_raw，其数据会被记录到trace.dat.cpu0。当结束记录时，这些文件会被合并到一个文件中，比如trace.dat。

使用trace-cmd不需要手动挂载debugfs，它会自动挂载debugfs并寻找其挂载路径。

Record

基本参数

record的参数实际上对应了Ftrace在debugfs中的接口。

  • -e表示跟踪一个event，可以使用event名，子系统名，如果要跟踪多个event，可以多次使用该选项，或者all用来监控所有的event。可以使用sudo trace-cmd list -e来查看当前系统中有哪些支持跟踪的event。

  • -f表示对一个event中的某些域（field）进行过滤，只对其之前-e设置的event生效，因此一般紧跟在-e之后。要查看一个event有哪些域可以进行过滤，可以查看/sys/kernel/debug/tracing/events/<subsystem>/<event>/format，其中subsystem和event可以通过sudo trace-cmd list -e来获得。

  • -p表示使用一个plugin，实际上就是Ftrace中的tracer，可以使用sudo trace-cmd list -t查看当前系统支持哪些tracer。同一时刻只能使用一种plugin。

  • -l表示后面跟上函数名，表示只跟踪这个函数；-n后面跟上函数名，表示不跟踪这个函数，这两个选项均可多次使用来设置多个函数。可以通过sudo trace-cmd list -f查看哪些函数可以进行过滤。注意，函数过滤仅在使用function和function_graph这两个plugin时有效。

  • -M表示CPU掩码，使用16进制表示，每一位表示一个CPU，例如4(16) = 100(2)，因此只有CPU2的数据会被记录。

下面是一些例子：

  • 跟踪内核中中断的执行时间

    1
    sudo trace-cmd record -p function_graph -l do_IRQ -e irq_handler_entry sleep 1
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    CPU 1 is empty
    CPU 2 is empty
    CPU 3 is empty
    CPU 5 is empty
    CPU 6 is empty
    CPU 7 is empty
    cpus=8
              <idle>-0     [000] 1251617.972283: funcgraph_entry:                   |  do_IRQ() {
              <idle>-0     [000] 1251617.972302: irq_handler_entry:    irq=10 name=virtio0
              <idle>-0     [000] 1251617.972359: funcgraph_exit:       + 77.853 us  |  }
              <idle>-0     [004] 1251618.092777: funcgraph_entry:                   |  do_IRQ() {
              <idle>-0     [004] 1251618.092792: irq_handler_entry:    irq=15 name=ata_piix
              <idle>-0     [004] 1251618.092892: funcgraph_exit:       ! 116.705 us |  }
              <idle>-0     [004] 1251618.092907: funcgraph_entry:                   |  do_IRQ() {
              <idle>-0     [004] 1251618.092908: irq_handler_entry:    irq=15 name=ata_piix
              <idle>-0     [004] 1251618.092954: funcgraph_exit:       + 47.463 us  |  }

  • 通过bytes_req域过滤kmalloc_node event

    1
    trace-cmd record -e kmalloc_node -f 'bytes_req > 1000'
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    name: kmalloc_node
    ID: 515
    format:
            field:unsigned short common_type;       offset:0;       size:2; signed:0;
            field:unsigned char common_flags;       offset:2;       size:1; signed:0;
            field:unsigned char common_preempt_count;       offset:3;       size:1; signed:0;
            field:int common_pid;   offset:4;       size:4; signed:1;

            field:unsigned long call_site;  offset:8;       size:8; signed:0;
            field:const void * ptr; offset:16;      size:8; signed:0;
            field:size_t bytes_req; offset:24;      size:8; signed:0;
            field:size_t bytes_alloc;       offset:32;      size:8; signed:0;
            field:gfp_t gfp_flags;  offset:40;      size:4; signed:0;
            field:int node; offset:44;      size:4; signed:1;
        [...]

通过网络传输

对于一些存储空间非常有限，或者存储器速度较慢的设备，可以通过网络将trace.dat保存到其它设备中。

  • host

    1
    trace-cmd listen -p 12345 -D -d /images/tracing/ -l /images/tracing/logfile

    -p：端口

    -D：daemon模式

    -d：trace文件保存的位置

    -l：log文件保存的位置

  • client

    1
    trace-cmd record -N 192.168.1.100:12345 -e ext4 ls

    -N：IP地址和端口号

Report

此时，我们已经拿到了trace.dat，现在需要对其进行分析。因为其中可能包含海量的数据，所以仍然需要过滤。

trace-cmd

1
trace-cmd report

trace-cmd本身提供了非常灵活且强大的过滤功能，但是使用起来也非常繁琐，尤其是当处理大量数据时，因此，这里不对其进行详细介绍，有需要可以通过man trace-cmd-report了解其详细用法。

kernelshark

kernelshark是一个用来查看trace.dat的GUI程序，完整的文档请访问KernelShark。

总结

以上是对Ftrace的两个前端工具——trace-cmd和kernelshark的简单介绍，通过这两个工具，可以更加容易的使用Ftrace接口，从而更加高效的调试、优化内核。

参考资料

trace-cmd: A front-end for Ftrace

Using KernelShark to analyze the real-time scheduler

KernelShark