一目了然-火焰图初探

大家好，我是程栩，一个专注于性能的大厂程序员，分享包括但不限于计算机体系结构、性能优化、云原生的知识。

今天我们来聊一聊火焰图，一个很经典的性能可视化工具。本文是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

• 火焰图生成与分析