Linux 下用火焰图进行性能分析

软件的性能分析往往需要查看 CPU 耗时了解瓶颈在哪里。火焰图 (flame graph) 是性能分析的利器。1. 火焰图简介很多人感冒发烧的时候往往会模仿神农氏尝百草的路子先尝尝抗病毒的药再试试抗细菌的药甭管家里有什么药挨个试什么中药西药瞎猫总会碰上死耗子如此做法自然是不可取的正确的做法应该是去医院验个血确诊后再对症下药。让我们回想一下我们一般是如何调试程序的通常是在没有数据的情况下依靠主观臆断来瞎蒙而不是考虑问题到底是什么引起的毫无疑问调优程序性能问题的时候同样需要对症下药。1.1. 火焰图常见的火焰图类型有 On-CPUOff-CPU还有 MemoryHot/ColdDifferential 等等。关于火焰图详细的介绍可以参考 Blazing Performance with Flame Graphs简而言之整个图形看起来就像一团跳动的火焰这也正是其名字的由来。燃烧在火苗尖部的就是 CPU 正在执行的操作不过需要说明的是颜色是随机的本身并没有特殊的含义纵向表示调用栈的深度横向表示消耗的时间。因为调用栈在横向会按照字母排序并且同样的调用栈会做合并所以一个格子的宽度越大越说明其可能是瓶颈。综上所述主要就是看那些比较宽大的火苗特别留意那些类似平顶山的火苗。要生成火焰图必须要有一个顺手的 Tracer 工具如果操作系统是 Linux 的话那么选择通常是 perfsystemtap 中的一种。其中 perf 相对更常用因为它时 Linux Kernel 内置的性能调优工具多数 Linux 都包含了它有兴趣的读者稍后可以参考 Linux Profiling at Netflix 中的介绍尤其是里面关于如何处理 Broken stacks 问题的描述建议多看几遍而 systemtap 相对更强大不过缺点是你需要先学会它本身的编程语言。早期火焰图在 Nginx 和 社区比较活跃如果你是一个 Nginx 开发或者优化人员那么我强烈推荐你使用春哥的 nginx-systemtap-toolkit乍一看名字你可能会误以为这个工具包是 nginx 专用的实际上这里面很多工具适用于任何 C/CPP 语言编写的程序程序功能sample-bt用来生成 On-CPU 火焰图的采样数据 (DEMO)sample-bt-off-cpu用来生成 Off-CPU 火焰图的采样数据 (DEMO)1.2. On/Off-CPU 火焰图那么什么时候使用 On-CPU 火焰图? 什么时候使用 Off-CPU 火焰图呢?取决于当前的瓶颈到底是什么如果是 CPU 则使用 On-CPU 火焰图如果是 IO 或锁则使用 Off-CPU 火焰图。如果无法确定那么可以通过压测工具来确认通过压测工具看看能否让 CPU 使用率趋于饱和如果能那么使用 On-CPU 火焰图如果不管怎么压CPU 使用率始终上不来那么多半说明程序被 IO 或锁卡住了此时适合使用 Off-CPU 火焰图。如果还是确认不了那么不妨 On-CPU 火焰图和 Off-CPU 火焰图都搞搞正常情况下它们的差异会比较大如果两张火焰图长得差不多那么通常认为 CPU 被其它进程抢占了。在采样数据的时候最好通过压测工具对程序持续施压以便采集到足够的样本。关于压测工具的选择如果选择 ab 的话那么务必记得开启 -k 选项以避免耗尽系统的可用端口。此外我建议尝试使用诸如 wrk 之类更现代的压测工具。1.3. 火焰图可视化生成器Brendan D.Gregg 的 Flame Graph 工程实现了一套生成火焰图的脚本。Flame Graph 项目位于 GitHub上 GitHub - brendangregg/FlameGraph: Stack trace visualizer生成和创建火焰图需要如下几个步骤流程描述脚本捕获堆栈使用perf/systemtap/dtrace等工具抓取程序的运行堆栈perf/systemtap/dtrace折叠堆栈trace工具抓取的系统和程序运行每一时刻的堆栈信息需要对他们进行分析组合将重复的堆栈累计在一起从而体现出负载和关键路径FlameGraph中的stackcollapse程序生成火焰图分析 stackcollapse 输出的堆栈信息生成火焰图flamegraph.pl不同的 trace 工具抓取到的信息不同因此Flame Graph提供了一系列的stackcollapse工具。stackcollapse描述stackcollapse.plfor DTrace stacksstackcollapse-perf.plfor Linux perf_events “perf script” outputstackcollapse-pmc.plfor FreeBSD pmcstat -G stacksstackcollapse-stap.plfor SystemTap stacksstackcollapse-instruments.plfor XCode Instrumentsstackcollapse-vtune.plfor Intel VTune profilesstackcollapse-ljp.awkfor Lightweight Java Profilerstackcollapse-jstack.plfor Java jstack(1) outputstackcollapse-gdb.plfor gdb(1) stacksstackcollapse-go.plfor Golang pprof stacksstackcollapse-vsprof.plfor Microsoft Visual Studio profiles2. perf 实现原理来思考一下如果让我们来设计一个统计程序中各个函数占用 CPU 时间的方案应该如何设计最简单的方案就是在各个函数的开始记录当前时间然后在函数执行结束后使用当前时间减去函数开始执行时的时间得到函数的执行时间总时长。如下伪代码void func1() { ... } void func2() { ... } int main(int argc, char *argv[]) { int start_time, total_time; start_time now(); func1(); total_time now() - start_time; printf(func1() spent %d\n, total_time); start_time now(); func2(); total_time now() - start_time; printf(func2() spent %d\n, total_time); }虽然上述方式可以统计程序中各个函数的耗时情况但却存在很多问题代码入侵度高。由于要对每个函数进行耗时记录所以必须在调用函数前和调用函数后加入统计代码。统计函数耗时并不能反映该函数的真实 CPU 使用率。比如函数内部调用了导致进程休眠的系统调用如sleep这时函数实际上是不使用CPU的但函数的耗时却统计了休眠的时间。对性能影响较大。由于程序中所有函数都加入统计代码所以对性能的影响是非常大的。所以我们需要一个系统它能够避免上述问题零代码入侵。能够真实反映函数的 CPU 使用率。对性能影响较小。perf 就是为了解决上述问题而生的我们先来介绍一下 perf 的原理。2.1. 采样为了减小对程序性能的影响perf 并不会在每个函数加入统计代码取而代之的统计方式是采样。采样的原理是设置一个定时器当定时器触发时查看当前进程正在执行的函数然后记录下来。如下图所示如上图所示每个cpu-clock是一个定时器的触发点。在 6 次定时器触发点中函数func1被命中了 3 次函数func2被命中了 1 次函数func3被命中了 2 次。所以我们可以推测出函数 func1 的 CPU 使用率最高。2.2. 排序如果程序有成千上万的函数那么采样出来的数据可能非常多这个时候就需要对采样的数据进行排序。为了对采样数据进行排序perf 使用红黑树这种数据结构如下图所示如上图所示在 perf 采样的数据中有 7 个函数被统计了命中次数perf 使用采样到的数据构建一棵红黑树。根据红黑树的特性最右边的节点就是被命中最多的函数这样就能把程序中 CPU 使用率最高的函数找出来。3. 安装perf安装perf工具执行如下命令sudo apt-get install linux-tools-common linux-tools-$(uname -r)查看perf工具的版本执行如下命令perf --version下载FlameGraphgit clone https://github.com/brendangregg/FlameGraph.git4. 用 perf 生成火焰图4.1. perf 采集数据让我们从 perf 命令performance 的缩写讲起它是 Linux 系统原生提供的性能分析工具会返回 CPU 正在执行的函数名以及调用栈(stack)sudo perf record -F 99 -p 3887 -g --sleep 30perf record 表示采集系统事件没有使用 -e 指定采集事件则默认采集 cycles即 CPU clock 周期-F 99 表示每秒 99 次-p 13204 是进程号即对哪个进程进行分析-g 表示记录调用栈sleep 30 则是持续 30 秒。-F 指定采样频率为 99Hz每秒99次如果 99次 都返回同一个函数名那就说明 CPU 这一秒钟都在执行同一个函数可能存在性能问题。示例sudo perf record -g ./my_program arg1 arg2其中my_program就是需要运行的程序。运行后会产生一个庞大的文本文件。如果一台服务器有 16 个 CPU每秒抽样 99 次持续 30 秒就得到 47,520 个调用栈长达几十万甚至上百万行。为了便于阅读perf record 命令可以统计每个调用栈出现的百分比然后从高到低排列。sudo perf report -n --stdio4.2. 生成火焰图首先用 perf script 工具对 perf.data 进行解析# 生成折叠后的调用栈 perf script -i perf.data perf.unfold将解析出来的信息存下来供生成火焰图首先用 stackcollapse-perf.pl 将 perf 解析出的内容 perf.unfold 中的符号进行折叠# 生成火焰图 ./stackcollapse-perf.pl perf.unfold perf.folded最后生成 svg 图./flamegraph.pl perf.folded perf.svg我们可以使用管道将上面的流程简化为一条命令perf script | FlameGraph/stackcollapse-perf.pl | FlameGraph/flamegraph.pl process.svg生成火焰图5. 解析火焰图最后就可以用浏览器打开火焰图进行分析啦。5.1. 火焰图的含义火焰图是基于 stack 信息生成的 SVG 图片用来展示 CPU 的调用栈。y 轴表示调用栈每一层都是一个函数。调用栈越深火焰就越高顶部就是正在执行的函数下方都是它的父函数。x 轴表示抽样数如果一个函数在 x 轴占据的宽度越宽就表示它被抽到的次数多即执行的时间长。注意x 轴不代表时间而是所有的调用栈合并后按字母顺序排列的。火焰图就是看顶层的哪个函数占据的宽度最大。只要有“平顶” (plateaus)就表示该函数可能存在性能问题。颜色没有特殊含义因为火焰图表示的是 CPU 的繁忙程度所以一般选择暖色调。5.2. 互动性火焰图是 SVG 图片可以与用户互动。鼠标悬浮火焰的每一层都会标注函数名鼠标悬浮时会显示完整的函数名、抽样抽中的次数、占据总抽样次数的百分比点击放大在某一层点击火焰图会水平放大该层会占据所有宽度显示详细信息。左上角会同时显示“Reset Zoom”点击该链接图片就会恢复原样。搜索按下 Ctrl F 会显示一个搜索框用户可以输入关键词或正则表达式所有符合条件的函数名会高亮显示。5.3. 局限两种情况下无法画出火焰图需要修正系统行为。调用栈不完整当调用栈过深时某些系统只返回前面的一部分比如前10层。函数名缺失有些函数没有名字编译器只用内存地址来表示比如匿名函数。5.4. 浏览器的火焰图Chrome 浏览器可以生成页面脚本的火焰图用来进行 CPU 分析。打开开发者工具切换到 Performance 面板。然后点击录制按钮开始记录数据。这时可以在页面进行各种操作然后停止录制。这时开发者工具会显示一个时间轴。它的下方就是火焰图。浏览器的火焰图与标准火焰图有两点差异它是倒置的即调用栈最顶端的函数在最下方x 轴是时间轴而不是抽样次数。6. 红蓝分叉火焰图参考 http://www.brendangregg.com/blog/2014-11-09/differential-flame-graphs.html幸亏有了 CPU 火焰图 (flame graphs)CPU 使用率的问题一般都比较好定位。但要处理性能回退问题就要在修改前后或者不同时期和场景下的火焰图之间不断切换对比来找出问题所在这感觉就是像在太阳系中搜寻冥王星。虽然这种方法可以解决问题但我觉得应该会有更好的办法。所以下面就隆重介绍红/蓝差分火焰图 (red/blue differential flame graphs)6.1. 红蓝差分火焰图示例上面是一副交互式 SVG 格式图片。图中使用了两种颜色来表示状态红色表示增长蓝色表示衰减。这张火焰图中各火焰的形状和大小都是和第二次抓取的 profile 文件对应的 CPU 火焰图是相同的。其中y 轴表示栈的深度x 轴表示样本的总数栈帧的宽度表示了 profile 文件中该函数出现的比例最顶层表示正在运行的函数再往下就是调用它的栈。在下面这个案例展示了在系统升级后一个工作载荷的 CPU 使用率上升了。下面是对应的 CPU 火焰图SVG 格式通常在标准的火焰图中栈帧和栈塔的颜色是随机选择的。而在红/蓝差分火焰图中使用不同的颜色来表示两个 profile 文件中的差异部分。在第二个 profile 中 deflate_slow() 函数以及它后续调用的函数运行的次数要比前一次更多所以在上图中这个栈帧被标为了红色。可以看出问题的原因是ZFS的压缩功能被启用了而在系统升级前这项功能是关闭的。这个例子过于简单我甚至可以不用差分火焰图也能分析出来。但想象一下如果是在分析一个微小的性能下降比如说小于5%而且代码也更加复杂的时候问题就为那么好处理了。6.2. 红蓝差分火焰图简介这个事情我已经讨论了好几年了最终我自己编写了一个我个人认为有价值的实现。它的工作原理是这样的抓取修改前的堆栈 profile1 文件抓取修改后的堆栈 profile2 文件使用 profile2 来生成火焰图。(这样栈帧的宽度就是以 profile2 文件为基准的)使用 “2-1” 的差异来对火焰图重新上色。上色的原则是如果栈帧在 profile2 中出现出现的次数更多则标为红色否则标为蓝色。色彩是根据修改前后的差异来填充的。这样做的目的是同时使用了修改前后的 profile 文件进行对比在进行功能验证测试或者评估代码修改对性能的影响时会非常有用。新的火焰图是基于修改后的 profile 文件生成所以栈帧的宽度仍然显示了当前的CPU消耗。通过颜色的对比就可以了解到系统性能差异的原因。只有对性能产生直接影响的函数才会标注颜色比如说正在运行的函数它所调用的子函数不会重复标注。6.3. 生成红/蓝差分火焰图作者的 GitHub 仓库 FlameGrdph 中实现了一个程序脚本difffolded.pl 用来生成红蓝差分火焰图。为了展示工具是如何工作的用 Linux perf_events 来演示一下操作步骤。你也可以使用其他 profiler/tracer。抓取修改前的profile 1文件:# 抓取数据 perf record -F 99 -a -g -- sleep 30 # 解析数据生成堆栈信息 perf script out.stacks1 # 折叠堆栈 ./stackcollapse-perf.pl ../out.stacks1 out.folded1一段时间后 (或者程序代码修改后)抓取 profile 2 文件# 抓取数据 perf record -F 99 -a -g -- sleep 30 # 解析数据生成堆栈信息 perf script out.stacks2 # 折叠堆栈 ./stackcollapse-perf.pl ../out.stacks2 out.folded2生成红蓝差分火焰图./difffolded.pl out.folded1 out.folded2 | ./flamegraph.pl diff2.svgdifffolded.pl 只能对 “折叠” 过的堆栈 profile 文件进行操作折叠操作是由前面的 stackcollapse 系列脚本完成的。 脚本共输出 3 列数据其中一列代表折叠的调用栈另两列为修改前后 profile 文件的统计数据。func_a;func_b;func_c 31 33 [...]在上面的例子中 “funca()-funcb()-func_c()” 代表调用栈这个调用栈在 profile1文件中共出现了31次在profile2文件中共出现了33次。然后使用flamegraph.pl脚本处理这3列数据会自动生成一张红/蓝差分火焰图。再介绍一些有用的选项其他选项描述difffolded.pl -n这个选项会把两个profile文件中的数据规范化使其能相互匹配上。如果你不这样做抓取到所有栈的统计值肯定会不相同因为抓取的时间和CPU负载都不同。这样的话看上去要么就是一片红负载增加要么就是一片蓝负载下降。-n选项对第一个profile文件进行了平衡这样你就可以得到完整红/蓝图谱difffolded.pl -x这个选项会把16进制的地址删掉。profiler时常会无法将地址转换为符号这样的话栈里就会有16进制地址。如果这个地址在两个profile文件中不同这两个栈就会认为是不同的栈而实际上它们是相同的。遇到这样的问题就用-x选项搞定flamegraph.pl --negate用于颠倒红/蓝配色。在下面的章节中会用到这个功能6.4. 不足之处虽然红/蓝差分火焰图很有用但实际上还是有一个问题如果一个代码执行路径完全消失了那么在火焰图中就找不到地方来标注蓝色。你只能看到当前的 CPU 使用情况而不知道为什么会变成这样。一个办法是将对比顺序颠倒画一个相反的差分火焰图。例如上面的火焰图是以修改前的 profile 文件为基准颜色表达了将要发生的情况。右边使用蓝色高亮显示的部分从中可以看出修改后 CPU Idle 消耗的 CPU 时间会变少。(其实通常会把 cpuidle 给过滤掉使用命令行 grep -v cpuidle图中把消失的代码也突显了出来或者应该是说没有突显因为修改前并没有使能压缩功能所以它没有出现在修改前的 profile 文件了也就没有了被表为红色的部分。下面是对应的命令行./difffolded.pl out.folded2 out.folded1 | ./flamegraph.pl --negate diff1.svg这样把前面生成 diff2.svg 一并使用我们就能得到火焰图信息描述diff1.svg宽度是以修改前profile文件为基准颜色表明将要发生的情况diff2.svg宽度是以修改后profile文件为基准颜色表明已经发生的情况如果是在做功能验证测试我会同时生成这两张图。6.5. CPI 火焰图这些脚本开始是被使用在CPI火焰图的分析上与比较修改前后的 profile 文件不同在分析 CPI 火焰图时可以分析 CPU 工作周期与停顿周期的差异变化这样可以凸显出CPU的工作状态来。6.6. 其他的差分火焰图也有其他人做过类似的工作。Robert Mustacchi 在不久前也做了一些尝试他使用的方法类似于代码检视时的标色风格只显示了差异的部分红色表示新增上升的代码路径蓝色表示删除下降的代码路径。一个关键的差别是栈帧的宽度只体现了差异的样本数。右边是一个例子。这个是个很好的主意但在实际使用中会感觉有点奇怪因为缺失了完整profile文件的上下文作为背景这张图显得有些难以理解。Cor-Paul Bezemer也制作了一种差分显示方法flamegraphdiff他同时将3张火焰图放在同一张图中修改前后的标准火焰图各一张下面再补充了一张差分火焰图但栈帧宽度也是差异的样本数。上图是一个例子。在差分图中将鼠标移到栈帧上3张图中同一栈帧都会被高亮显示。这种方法中补充了两张标准的火焰图因此解决了上下文的问题。我们3人的差分火焰图都各有所长。三者可以结合起来使用Cor-Paul方法中上方的两张图可以用我的 diff1.svg 和 diff2.svg。下方的火焰图可以用Robert的方式。为保持一致性下方的火焰图可以用我的着色方式蓝-白-红。6.7. 总结如果你遇到了性能回退问题红/蓝差分火焰图是找到根因的最快方式。这种方式抓取了两张普通的火焰图然后进行对比并对差异部分进行标色红色表示上升蓝色表示下降。差分火焰图是以当前“修改后”的profile文件作为基准形状和大小都保持不变。因此你通过色彩的差异就能够很直观的找到差异部分且可以看出为什么会有这样的差异。差分火焰图可以应用到项目的每日构建中这样性能回退的问题就可以及时地被发现和修正。参考文献Linux下用火焰图进行性能分析_CHENG Jian的博客-CSDN博客一文看懂 Linux 性能分析perf 原理