大家好,我是程栩,一个专注于性能的大厂程序员,分享包括但不限于计算机体系结构、性能优化、云原生的知识。
今天我们来聊一聊火焰图,一个很经典的性能可视化工具。本文是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
本身也是一个负载,如果频率过高也会影响到机器自身的执行。我们需要合理的选择观测频率。对于类似观测的成本,也有诸多研究,我们后续会有一些介绍。
小结
今天的介绍就到这里,我们今天主要介绍了如下的内容: