完全掌握火焰图的作图原理&看图技巧
概要
有好长一段时间,兴趣爱好都落在了程序性能观测这个领域。之所以有兴趣,一来是解决一下工作中的问题,在这平淡的生活中寻找一丝快乐;二来也是想以史为鉴,以后在自己的代码里尽可能不要犯同样的错。
当局者迷,会体现在生活中的方方面面,正如写程序的人不知道程序的哪个函数会成为热点一样,我以前上来就是一张火焰图,也没有交代这个怎么得来的,现在准备把这一块补一下。
造场景
火焰图可用来分析程序中的热点函数,找出那些执行耗时比较长的函数(大多数情况下这些函数是性能问题的根源所在),为后面的代码优化指明方向。
要想讲清楚这个(火焰图),目前没有想到合适的方法;如若把我走过的弯路和正道都讲一遍,就认识而言也算得上比较全面了。
扯远了,要讲的毕竟不是什么屠龙之术。trace 是要真刀真枪干的,还是先把环境搞起来。看下面这段 cpp 我就用它做原型了。
#include <iostream>
void foo() {
int j = 0;
for(int i=0; i< 1000; i++)
{
j = i * 10 + 1;
}
}
void bar() {
int j = 0;
for(int i=0; i< 2000; i++)
{
j = i * 10 + 1;
}
}
int main(int, char**) {
while(true)
{
foo();
bar();
}
}
程序的逻辑非常直接, main 函数会不断地调用 foo 和 bar 这两个函数。其实仔细看 foo 和 bar 的逻辑几乎一样,foo 会给 j 赋值 1k 次,而 bar 会给 j 赋值 2k 次。如果说 foo 的开销是 1 那么 bar 的开销就应该是 2 ,整个 main 的开销差不多就是 3 。
把程序编译安装到 /usr/bin/fires 后面这个程序就是我的实验环境了。注意这个安装路径我们会在后面的 trace 里面用到它。
性能测试
前面的分析得知,如果说 main 函数运行了 3s ,那么应该是有 1s 花在了 foo 函数上,有 2s 花在了 bar 函数上。至于是不是这个比例还要用数字说话,这个数据确认起来也相对简单,我们只要把程序运行起来把各个函数的耗时统计一下,就行了。
1. 在后台运行程序
nohup /usr/bin/fires &
top
Tasks: 128 total, 2 running, 126 sleeping, 0 stopped, 0 zombie
%Cpu(s): 50.2 us, 0.0 sy, 0.0 ni, 49.8 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
MiB Mem : 7685.1 total, 712.8 free, 3708.5 used, 3263.9 buff/cache
MiB Swap: 0.0 total, 0.0 free, 0.0 used. 3573.2 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2509283 root 20 0 5828 2000 1832 R 100.0 0.0 0:10.55 fires
2369444 root 20 0 51936 11068 4480 S 0.4 0.1 2:16.32 redis-s+
1 root 20 0 169420 11492 7248 S 0.0 0.1 2:51.53 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:01.45 kthreadd
可以看到当程序运行起来之后它自己独占了一个核,并且把这个核心跑到了 100% 。
2. 统计 foo | bar 函数的执行耗时,这里我就直接用 ebpf 来追踪,foo 函数的耗时统计代码如果。
#!/usr/bin/bpftrace
BEGIN {
printf("start trace fires user-function foo calls .... Hit Ctrl-C to end.\n");
@btrace_begin[$1] = nsecs;
@counts[$1] = 0;
@duration[$1] = 0;
}
uprobe:/usr/bin/fires:foo {
@start[$1] = nsecs;
@counts[$1] = @counts[$1] + 1;
}
uretprobe:/usr/bin/fires:foo /@start[$1]/ {
$temp = nsecs;
if($temp > @start[$1]) {
@duration[$1] = @duration[$1] + (int64)($temp - @start[$1] );
}
}
END {
@btrace_end[$1] = nsecs;
printf("\ntrace %d (s) \n", (@btrace_end[$1] - @btrace_begin[$1])/1e9);
printf("function foo called %d times, spend %d ms", @counts[$1], (int64)(@duration[$1] / 1e6));
delete(@btrace_begin[$1]);
delete(@btrace_end[$1]);
delete(@start[$1]);
delete(@counts[$1]);
delete(@duration[$1]);
}
3. foo 的耗时统计(追踪了 9s ,发现 foo 总共执行了 3.2s )
./trace-foo.bt ~
Attaching 4 probes...
start trace fires user-function foo calls .... Hit Ctrl-C to end.
trace 9 (s)
function foo called 982712 times, spend 3266 ms
4. bar 的耗时统计(追踪了 6s ,发现 bar 总共执行了 4.1s)
./trace-bar.bt ~
Attaching 4 probes...
start trace fires user-function bar calls .... Hit Ctrl-C to end.
trace 6 (s)
function bar called 708620 times, spend 4069 ms
trace 的结果,基本上和分析源码得出来的结论差不多。foo 的开销大概是总时间的 1/3 ,bar 的开销大概是总时间的 2/3 。也就是说我们通过 trace 看到了程序执行中最为耗时的调用 “bar 函数”。
对于一个像 MySQL 这么大的项目我们不可能,每一个函数都去 trace 来发现问题,这么做的工作量就太大了。
火焰图的理论基础
数学啊!它有时能把复杂的事情搞简单,如果我们不想全量 trace 的话,我们可以像《统计学》一样抽样啊!
函数的调用在计算机里面是通过压栈来完成的,一个函数执行完成之后就会从栈中弹出,对于我们这个程序的函数调用栈只有以下两种可能。要么它在执行 foo ,要么它在执行 bar 。
如果我们在程序运行的过程中,去抽样&统计函数调用栈各个情况和它的占比,只要样本数据够多,执行 foo 的情况差不多会占 33.3%,执行 bar 的情况差不多会占 66.6%.
这能说明什么呢?你去采样了 100 次,有 66 次是 bar 占着 cpu 在干活,说明主要的耗时就在 bar 这个函数上呀。如果有办法把 bar 运行时间降下来,那节约的是时间,提升的是性能。在想到解决办法之前,更加重要的一步是发现问题的根源,火焰图可以帮我们发现这类问题。
如果在这里直接上火焰图的话,那就是忘了初心了。现在我打算用 excel 手工一步步把画火焰图画出来,假设我们采样了 3 次,那么我们的结果有可能是像下面这样的。
三个分裂的图,这样不够直观。现在处理一下把它合成一张图,在整理的过程中,还要尽可能把同一个函数多个样本点放在一起;在这里我把两个 bar 合并在一起。
一个手工用 excel 搞的火焰图就这样出来了。
火焰图工具
可以看到理论还是相当的简单的,正是由于简单,导致火焰图的工具也是百花齐放;不同工具其定位也不尽相同,比如 async-profiler 定位在 java 平台,bcc 定位在 C/C++ 与 linux-kernel 这个层面。
由于我上面写的是一段 C++ 程序,我这里就用 bcc 演示一下完整的画图过程吧。其实就两步
1. 采样
ps -ef | grep fires
root 2509283 1 99 Oct04 ? 19:51:01 /usr/bin/fires
profile -p 2509283 -af 7 > /tmp/fires.stacks
2. 画图
cd /tmp/FlameGraph
./flamegraph.pl --color=io --title=fires < /tmp/fires.stack > /tmp/fires.svg
3. 由于最终的图片是 svg 格式的,所以用浏览器就能直接看,算比较方便。看 bar 占用 2/3 ,foo 占用 1/3 和我们上面用 excel 画出来的是一个比例。
人工自己画 3 ~ 5 个堆栈就差不多了,用工具画几千几万个都不成问题。工具方便了我们扩大样本数量,让结果更加可信。
总结
1. 关于火焰图怎么看
第一步:从下往上看,找到最宽的那条,它就是主要矛盾。如果看不出什么问题,不要留恋,我们要再往上看。
第二步:重复第一步,直到看到了最上面。
相关文章
- 4 OpenResty & Lua 处理各类Http请求
- 剑指offer:Python 二进制中1的个数 &0xffffffff是什么意思?
- (void (*Visit)(const ElemType &))[通俗易懂]
- Es6参数展开&剩余参数
- 零零信安-D&D数据泄露报警日报【第19期】
- 正向代理&反向代理(校园网为例)
- 供应链中常见的“分仓&库存分配”原理
- AI理解不了“他她它”咋办?动词成为新突破口,机器人听到抹黄油就知道拿刀叉 | 清华AIR&北大&英特尔
- 一致性 Hash 算法原理&应用梳理
- 图机器学习(GML)&图神经网络(GNN)原理和代码实现(前置学习系列二)
- 【指针进阶三】实现C语言快排函数qsort&回调函数
- (五)定义 emits 类型&原生 DOM 元素类型
- 傻妞sillyGril&QQbot 真一键安装
- App Cleaner & Uninstaller for mac(最佳卸载程序和清洁助手)
- 本周六,快手&高瓴人工智能学院启动WWW23论文分享会,探讨推荐搜索领域热点(30个现场名额)
- AMP MySQL升级提升数据库性能的必要之举(amp mysql升级)
- 如何增加Oracle数据库的AMP值(amp值oracle)
- 聊天室php&mysql(四)