一目了然-火焰图初探
大家好，我是程栩，一个专注于性能的大厂程序员，分享包括但不限于计算机体系结构、性能优化、云原生的知识。
今天我们来聊一聊火焰图，一个很经典的性能可视化工具。本文是perf系列的第二篇文章，后续会继续介绍perf，包括用法、原理和相关的经典文章。
引
昨天我们说到，perf record的结果数据是一条条数据的格式，可以使用perf report来进行数据的可视化查看，我们也可以基于这个数据生成火焰图(FlameGraph)。今天，我们介绍关于火焰图的两个问题：
- 如何基于
perf record的数据生成火焰图 - 如何看懂火焰图及注意点
注：今天我们介绍的是on-cpu火焰图，也即在CPU上执行情况的火焰图。
生成火焰图
在生成火焰图之前，我们需要有调用栈的数据，这需要我们在执行perf record的时候带上-g选项表示记录调用栈，否则就不会有相关的调用栈数据。
# 收集60秒的调用栈数据
# -F 999 表示收集的频率
# -a 表示收集全部CPU数据 -g表示记录调用栈数据
[root@VM-16-2-centos ~]# perf record -F 999 -ag -- sleep 60
# 查看部分数据 如果不通过-i 指定文件会默认解析perf.data
[root@VM-16-2-centos ~]# perf script -i perf.data
sleep 1441923 [001] 12717072.272696: 1001001 cpu-clock:pppH:
ffffffff87ea9e01 vma_interval_tree_insert+0x31 ([kernel.kallsyms])
ffffffff87ebc0df vma_link+0x6f ([kernel.kallsyms])
ffffffff87ebf4a3 mmap_region+0x413 ([kernel.kallsyms])
ffffffff87ebfa7b do_mmap+0x38b ([kernel.kallsyms])
ffffffff87e996a2 vm_mmap_pgoff+0xd2 ([kernel.kallsyms])
ffffffff87ebd058 ksys_mmap_pgoff+0x1b8 ([kernel.kallsyms])
ffffffff87c042bb do_syscall_64+0x5b ([kernel.kallsyms])
ffffffff886000ad entry_SYSCALL_64_after_hwframe+0x65 ([kernel.kallsyms])
7f86e5fc47c7 mmap64+0x47 (/usr/lib64/ld-2.28.so)
swapper 0 [000] 12717072.273687: 1001001 cpu-clock:pppH:
ffffffff8857fece native_safe_halt+0xe ([kernel.kallsyms])
ffffffff8857fd8a __cpuidle_text_start+0xa ([kernel.kallsyms])
ffffffff88580020 default_idle_call+0x40 ([kernel.kallsyms])
ffffffff87d22a44 do_idle+0x1f4 ([kernel.kallsyms])
ffffffff87d22c7f cpu_startup_entry+0x6f ([kernel.kallsyms])
ffffffff89818267 start_kernel+0x51d ([kernel.kallsyms])
ffffffff87c00107 secondary_startup_64_no_verify+0xc2 ([kernel.kallsyms])
swapper 0 [001] 12717072.273705: 1001001 cpu-clock:pppH:
ffffffff8857fece native_safe_halt+0xe ([kernel.kallsyms])
ffffffff8857fd8a __cpuidle_text_start+0xa ([kernel.kallsyms])
ffffffff88580020 default_idle_call+0x40 ([kernel.kallsyms])
ffffffff87d22a44 do_idle+0x1f4 ([kernel.kallsyms])
ffffffff87d22c7f cpu_startup_entry+0x6f ([kernel.kallsyms])
ffffffff87c5929b start_secondary+0x19b ([kernel.kallsyms])
ffffffff87c00107 secondary_startup_64_no_verify+0xc2 ([kernel.kallsyms])
swapper 0 [000] 12717072.274685: 1001001 cpu-clock:pppH:
ffffffff8857fece native_safe_halt+0xe ([kernel.kallsyms])
ffffffff8857fd8a __cpuidle_text_start+0xa ([kernel.kallsyms])
ffffffff88580020 default_idle_call+0x40 ([kernel.kallsyms])
ffffffff87d22a44 do_idle+0x1f4 ([kernel.kallsyms])
ffffffff87d22c7f cpu_startup_entry+0x6f ([kernel.kallsyms])
ffffffff89818267 start_kernel+0x51d ([kernel.kallsyms])
ffffffff87c00107 secondary_startup_64_no_verify+0xc2 ([kernel.kallsyms])
如上的调用栈数据只有四条记录。如果只有这四条数据，我们大可以直接去寻找热点。但是由于cpu-clock事件每秒钟就会在一个CPU上执行1000次，在越大型的机器上其结果就会越多，很容易让人无法找到重点。例如，在一个2核的CPU上收集10S数据，频率为99赫兹，那么这十秒钟就会产生2*10*99 = 1980条调用栈数据。
我们可以借助Gregg（性能领域的大牛）的FlameGraph仓库中的脚本来帮助我们生成火焰图。
# 我们将调用栈数据存在名为perf.unfold的文件中
# 首先clone FlameGraph仓库
[root@VM-16-2-centos ~]# git clone https://github.com/brendangregg/FlameGraph
# 折叠调用栈
[root@VM-16-2-centos ~]# ./FlameGraph/stackcollapse.pl perf.unfold > perf.folded
# 查看一下折叠后数据 只展示了部分
[root@VM-16-2-centos ~]# cat perf.folded
swapper;secondary_startup_64_no_verify;start_kernel;cpu_startup_entry;do_idle;default_idle_call;__cpuidle_text_start;native_safe_halt 17977977960
sssd_nss;__vsnprintf_chk;__strchrnul_avx2 1001001
我们拿这条折叠后的调用栈数据和折叠前做比对，可以看到和前文的调用栈数据中的最后一条数据相关。那么，是怎么解析的呢？
从前后对比来看，我们可以看出这个进程的名字是swapper，其调用顺序分别是secondary_startup_64_no_verify、start_kernel一直到native_safe_halt，可以看出，对于折叠前的数据，其调用栈是栈顶在上，栈底在下的。也即，我们应该倒序的去看折叠前的调用栈。
那么，后面的这个17977977960又是代表什么呢？
我们可以看到在折叠后的数据中，还有着后缀为1001001的数据，这和调用栈数据中cpu-clock:pppH前面的数据是一致的。这是什么意思呢？
前面我们说到，我们使用的频率是999，如果把999乘1001001就是999,999,999，近似于1,000,000,000。而频率999是指一秒钟采样999次，那么对应每次采样的间隔就为1秒除以999。那么这里的1001001指的就是间隔，也即1001001纳秒。
为了验证这一点，我们以频率为100做了一次采样：
[root@VM-16-2-centos ~]# perf record -ag -F 100 -- sleep 5
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.444 MB perf.data (1000 samples) ]
[root@VM-16-2-centos ~]# perf script
swapper 0 [000] 12824405.925051: 10000000 cpu-clock:pppH:
ffffffff8857fece native_safe_halt+0xe ([kernel.kallsyms])
ffffffff8857fd8a __cpuidle_text_start+0xa ([kernel.kallsyms])
ffffffff88580020 default_idle_call+0x40 ([kernel.kallsyms])
ffffffff87d22a44 do_idle+0x1f4 ([kernel.kallsyms])
ffffffff87d22c7f cpu_startup_entry+0x6f ([kernel.kallsyms])
ffffffff89818267 start_kernel+0x51d ([kernel.kallsyms])
ffffffff87c00107 secondary_startup_64_no_verify+0xc2 ([kernel.kallsyms])
可以看到这里的时间就变成了10000000，那么乘以100就是1,000,000,000。
所以，我们可以这样认为：「折叠栈后面的数字就代表着在采样的情况下采中的时间」。
现在，我们已经生成了折叠栈，基于生成火焰图：
# 也可以用./FlameGraph/flamegraph.pl
[root@VM-16-2-centos ~]# perl FlameGraph/flamegraph.pl perf.folded > flame.svg
现在，我们就生成了一个火焰图。
火焰图
火焰图的含义
对于火焰图而言，如果从上而下做一条竖线，就是一个调用栈。例如从上图中我们可以看出从swapper到native_safe_halt的调用栈。
火焰图的纵轴则是代表着栈的深度，例如当采样的那一瞬间，栈的顶部是什么函数，其调用关系是什么样的；而火焰图的横轴则是占比，比如我们可以看到secondary_startup_64_no_verify函数往上有两个部分，start_kernel和start_secondary，且这两个的部分占比差不多。我们假设一共有1000次secondary_startup_64_no_verify在执行的时候被采样采中了，那么可能有460次其正在执行start_kernel函数，而剩下的540次在执行start_secondary函数。通过横轴占比的比重，我们就可以看出，某个函数大部分的时间集中在了哪个子函数的调用上，依次剥丝抽茧，就可以找到执行次数较多的函数。那么，在找到一个相对而言比较平的部分以后，我们就可以尝试去优化这个部分。根据Amdahl 定律，如果我们想要获得更好地加速比，我们就应当更多的去优化占比较大的部分。
注意点
值得注意的一点是，on-cpu火焰图并不包含「时序信息」，其只会给出占比的信息。那么如果想要借助其发现问题的话，就需要注意在这段采样的时间里，负载应当持续存在且平均。
举例来说，假设在十秒钟的采样中，有个热点函数foo采中了一千次，而整个CPU（YDService）一共采样一万次，那么从火焰图上看，可能这个热点函数就占了十分之一的CPU，也即它的宽度大概是十分之一左右：
火焰图
那么我们的中心可能就会放在other部分。这里的other是其他的泛指，而不是一个具体的函数。但是如果这个foo其实只存在了两秒钟呢？也就是说，在前两秒的采样中，foo就占到了整个负载的二分之一，那这可能就值得我们去做一些优化了。在整个图中，我们不一定会先优化foo，是因为其占比不高，但实际上foo执行的时候就会占到一半的负载，我们应该避免这样的现象出现。
那这个时候，一个问题就出现了，我们明明是做的是采样，可能频率只有99次一秒钟，怎么就能确定它是合理的呢？万一有这样一个函数恰好在采样的时候采中的次数比较多呢？
这是因为我们认为采样是一种缩放（大数定律），我们取的样本数量越多，就越会接近于期望的状态。那么什么是期望的状态呢？就是一个持续且变化不大的负载的等比例缩小。假设一秒钟会执行一万次CPU事件，其中有5000次执行foo，有5000次执行bar。假设我们采样两次，我们可能会得出全都是foo的结论，但是如果我们采用1000次，就会逐渐的趋向于500次foo和500次bar。
基于如上的想法，我们应当确保在进行perf采样的时候，机器的负载持续且平均。此外，perf本身也是一个负载，如果频率过高也会影响到机器自身的执行。我们需要合理的选择观测频率。对于类似观测的成本，也有诸多研究，我们后续会有一些介绍。
小结
今天的介绍就到这里，我们今天主要介绍了如下的内容：
关注我，学习更多性能知识，一起攀登性能之巅。
参考资料
- FlameGraph
- 火焰图生成与分析