作者简介：伟林，中年码农，从事过电信、手机、安全、芯片等行业，目前依旧从事Linux方向开发工作，个人爱好Linux相关知识分享。
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 -ysudo apt-get install freeglut3-dev libxmu-dev libxi-dev -ysudo apt-get install qtbase5-dev -y
2、下载源码：git clone https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/
3、编译安装：cd trace-cmdmake guisudo make install_gui- 2、从软件源安装，版本较旧：
sudo apt install trace-cmd kernelshark2.粗粒度分析
假设我们新增了一批函数名为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.bak3.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。
