使用ftrace分析函数性能

0. 背景

ftrace的功能非常强大，可以在系统的各个关键点上采集数据用以追踪系统的运行情况。既支持预设的静态插桩点(trace event)，也支持每个函数的动态插桩(function tracer)。还可以利用动态插桩来测量函数的执行时间(function graph tracer)。关于ftrace的详细操作和原理分析可以参考Linux ftrace一文。

本文的主要目的主要是利用ftrace来做新增代码的性能分析和优化，应用的主要场景如下：

我们在现有的代码中增加了一批新函数A_*()。

功能完成后，我们希望知道两个问题：

• Question 1、在运行过程中，新增的函数A_*()造成了多少的性能损失？
• Question 2、如果需要优化，怎样找出某个耗时比较大的A_xxx()函数具体开销在哪里？

1. trace-cmd工具的安装

我们可以手工操作/sys/kernel/debug/tracing路径下的大量的配置文件接口，来使用ftrace的强大功能。但是这些接口对普通用户来说太多太复杂了，我们可以使用对ftrace功能进行二次封装的一些命令来操作。

trace-cmd就是ftrace封装命令其中的一种。该软件包由两部分组成：

• 1、trace-cmd。提供了数据抓取和数据分析的功能。
• 2、kernelshark。可以用图形化的方式来详细分析数据，也可以做数据抓取。

首先我们需要安装trace-cmd工具，ubuntu下可以通过以下两种方式安装：

• 1、编译源码，安装最新版本：

1、安装依赖：
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

2、下载源码：
git clone https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/

3、编译安装：
cd trace-cmd
make gui
sudo make install_gui

• 2、从软件源安装，版本较旧：

sudo apt install trace-cmd kernelshark

2. 粗粒度分析

假设我们新增了一批函数名为vfs_*()，性能分析时我们可以先总体追踪一下这些函数的耗时，以及耗时在总体时间中的占比。即Question 1。

2.1 使用trace-cmd record -l func命令抓取数据

trace-cmd从per_cpu buffer中抓取原始数据/sys/kernel/debug/tracing/per_cpu/cpu0/trace_pipe_raw，所以它的开销小并且支持长时间抓取。

sudo trace-cmd record -p function_graph -l vfs_* -F cp -r ~/perf perf.bak

命令的详细参数含义如下：

• -p function_graph ：指定当前tracer为function_graph，只有function_graph才能测量函数执行时间
• -l vfs_* ：函数过滤，指定function_graph追踪哪些函数。function_graph有两种过滤条件可以配置：
  • -l func。实际对应set_ftrace_filter，这种方式插桩的开销较小，只会追踪顶层func的执行时间且支持*等通配符的设置。
  • -g func。实际对应set_graph_function，这种方式插桩的开销较大，但能追踪func以及func所有子函数的的执行时间，不支持*等通配符的设置。
• -F cp -r ~/perf perf.bak ：进程过滤，指定对cp -r ~/perf perf.bak这个进程进行追踪。也可以使用-P pid来指定进程。还可以不指定进程默认对全局进程追踪，例如sleep 10追踪10s。

因为-l func和-g func的特点，所以我们在粗粒度分析时使用-l func，在细粒度分析时使用-g func。这也是本文的一个精髓。

2.2 使用trace-cmd report --profile命令分析数据

所有的原始trace数据已经默认存储到trace.dat文件中了。

1、使用trace-cmd report命令可以把trace.dat解析成文本格式：

$ sudo trace-cmd report| more
...

# 注释 #    进程名-pid  CPU    时间戳(s)      函数入口/出口  耗时等级  函数耗时      函数名
              cp-3484  [006] 20010.128398: funcgraph_entry:      + 52.946 us  |  vfs_open();
              cp-3484  [006] 20010.128466: funcgraph_entry:      ! 212.370 us |  vfs_read();
              cp-3484  [006] 20010.128723: funcgraph_entry:        1.832 us   |  vfs_read();
              cp-3484  [006] 20010.128725: funcgraph_entry:        0.250 us   |  vfs_read();
              cp-3484  [006] 20010.128729: funcgraph_entry:        0.673 us   |  vfs_open();
              cp-3484  [006] 20010.128730: funcgraph_entry:        0.688 us   |  vfs_read();
              cp-3484  [006] 20010.128731: funcgraph_entry:        0.434 us   |  vfs_read();
              cp-3484  [006] 20010.129213: funcgraph_entry:        1.386 us   |  vfs_open();
              cp-3484  [006] 20010.129215: funcgraph_entry:                   |  vfs_statx_fd() {

文本主要格式的含义如上中文注释所示，我们读出开始的时间戳和结束的时间戳，就能计算出操作的总体时间。

2、trace-cmd report --profile命令可以对我们追踪的函数执行时间进行统计：

$ sudo trace-cmd report --profile
...

task: cp-3484   # 进程名和PID
#注释#         函数名       次数   总时长(ns)      平均时长(ns)   最大时长(ns)(时间戳s)         最小时长(ns)(时间戳s)
  Event: func: vfs_read() (6017) Total: 565900849 Avg: 94050 Max: 1827017(ts:20010.738236) Min:203(ts:20010.130418)
  Event: func: vfs_write() (3520) Total: 319047851 Avg: 90638 Max: 591045(ts:20010.398434) Min:3437(ts:20011.032217)
  Event: func: vfs_statx() (3865) Total: 49642741 Avg: 12844 Max: 1411479(ts:20010.626101) Min:924(ts:20010.718592)
  Event: func: vfs_mkdir() (690) Total: 9175927 Avg: 13298 Max: 63201(ts:20010.305020) Min:8868(ts:20010.939694)
  Event: func: vfs_getattr() (9529) Total: 5968390 Avg: 626 Max: 31850(ts:20010.459588) Min:260(ts:20010.718595)
  Event: func: vfs_statx_fd() (5666) Total: 5513205 Avg: 973 Max: 32808(ts:20010.539845) Min:434(ts:20010.508351)
  Event: func: vfs_open() (5668) Total: 4346891 Avg: 766 Max: 52724(ts:20010.128451) Min:236(ts:20011.152689)
  Event: func: vfs_getattr_nosec() (9529) Total: 2162038 Avg: 226 Max: 18470(ts:20010.182797) Min:91(ts:20010.718877)

--profile对数据进行了统计和排序。它按照进程为单位，对每个进程的监控函数的调用时间进行了统计，有调用次数、总时长、平均时长、最大/小时长，并且默认按照总时长进行了排序。

这样就很方便的找到哪个函数耗时最多，占比有多少。比如上例中耗时最多的是vfs_read()。

计算出所有函数的总体耗时，单位为ns：

// `$6`指定了第6列`总时长`
sudo trace-cmd report --profile | grep "Event: func:" | awk '{print $6}' | awk '{sum+=$1}END{print sum}'

也可以按照其他维度对数据进行排序：

// 按照`平均时长`进行排序，`k8`指定了第8列`平均时长`
sudo trace-cmd report --profile | grep "Event: func:" | sort -k8 -n -r      

3. 细粒度分析

上一节中我们使用粗粒度分析的方法找出了耗时最长的函数为vfs_read()，需要进一步分析vfs_read()的耗时究竟消耗在哪个子函数上。即Question 2。

3.1 使用trace-cmd record -g func命令抓取数据

上一节已经阐述了，抓取函数内部所有子函数的执行时间，需要使用-g func选项。trace数据已经默认存储到trace.dat文件中。

 sudo trace-cmd record -p function_graph -g vfs_read -F cp -r ~/perf perf.bak

3.2 使用trace-cmd report --profile命令分析数据

1、使用trace-cmd report命令可以把trace.dat解析成文本格式：

$ sudo trace-cmd report| more
...

              cp-3663  [006] 27162.447945: funcgraph_entry:                   |  vfs_read() {
              cp-3663  [006] 27162.447948: funcgraph_entry:                   |    smp_irq_work_interrupt() {
              cp-3663  [006] 27162.447948: funcgraph_entry:                   |      irq_enter() {
              cp-3663  [006] 27162.447948: funcgraph_entry:        0.122 us   |        rcu_irq_enter();
              cp-3663  [006] 27162.447949: funcgraph_exit:         0.396 us   |      }
              cp-3663  [006] 27162.447949: funcgraph_entry:                   |      __wake_up() {
              cp-3663  [006] 27162.447950: funcgraph_entry:                   |        __wake_up_common_lock() {
              cp-3663  [006] 27162.447950: funcgraph_entry:        0.093 us   |          _raw_spin_lock_irqsave();
              cp-3663  [006] 27162.447950: funcgraph_entry:        0.100 us   |          __wake_up_common();
              cp-3663  [006] 27162.447950: funcgraph_entry:        0.098 us   |          _raw_spin_unlock_irqrestore();
              cp-3663  [006] 27162.447950: funcgraph_exit:         0.666 us   |        }
              cp-3663  [006] 27162.447950: funcgraph_exit:         0.877 us   |      }

可以看到，抓出了函数的层次调用关系，以及在函数结束时打印出了函数执行时间。

2、trace-cmd report --profile命令对所有子函数进行统计：

$ sudo trace-cmd report --profile | more
...

task: cp-3663
  Event: func: vfs_read() (6011) Total: 1573004753 Avg: 261687 Max: 49374656(ts:27164.368077) Min:3394(ts:27162.503426)
  Event: func: __vfs_read() (6011) Total: 1530911551 Avg: 254685 Max: 49372111(ts:27164.368077) Min:1928(ts:27162.451416)
  Event: func: new_sync_read() (6009) Total: 1527333966 Avg: 254174 Max: 49371813(ts:27164.368076) Min:1891(ts:27162.503426)
  Event: func: ext4_file_read_iter() (6009) Total: 1523645073 Avg: 253560 Max: 49371449(ts:27164.368076) Min:1703(ts:27162.503426)
  Event: func: generic_file_read_iter() (6009) Total: 1519828915 Avg: 252925 Max: 49371191(ts:27164.368076) Min:1547(ts:27162.503426)
  Event: func: ondemand_readahead() (3073) Total: 755070718 Avg: 245711 Max: 2425224(ts:27164.891754) Min:282(ts:27162.906376)
  Event: func: __do_page_cache_readahead() (3073) Total: 752847053 Avg: 244987 Max: 2424918(ts:27164.891753) Min:91(ts:27162.906375)
  Event: func: page_cache_sync_readahead() (2484) Total: 406033723 Avg: 163459 Max: 1685271(ts:27162.480326) Min:477(ts:27162.906376)
  Event: func: ext4_readpages() (2966) Total: 365560885 Avg: 123250 Max: 1564052(ts:27162.480212) Min:19321(ts:27162.503496)

...

--profile对数据进行了统计和排序。它按照进程为单位，对每个进程的监控函数vfs_read()及其子函数的调用时间进行了统计，有调用次数、总时长、平均时长、最大/小时长，并且默认按照总时长进行了排序。

需要注意的是，上述的统计并没有呈现出函数的调用关系，所以它们的时长可能是相互包含的。另外因为任务切换的发生，数据中还记录了一些非追踪函数vfs_read()子函数以外的函数。但是以上的统计数据，对于排查重点函数还是非常有帮助的。

3.3 使用kernelshark图形化分析数据

trace-cmd report --profile主要是使用统计的方式来找出热点。如果要看vfs_read()一个具体的调用过程，除了使用上一节的trace-cmd report命令，还可以使用kernelshark图形化的形式来查看。

下图是使用kernelshark打开trace.dat文件，并且逐个分析vfs_read()子函数调用的示意图：

关于kernelshark的详细使用可以参考kernelshark guid。

参考文档：

1.Linux ftrace
2.build kernelshark
3.kernelshark guid
4.ftrace利器之trace-cmd和kernelshark
5.通过trace-cmd和kernelshark简化Ftrace的使用