提供了编程的基础技术教程

zl程序教程

您现在的位置是：首页 >  Java

当前栏目

完全掌握火焰图的作图原理&看图技巧

2023-02-18 16:34:20 时间

概要

有好长一段时间，兴趣爱好都落在了程序性能观测这个领域。之所以有兴趣，一来是解决一下工作中的问题，在这平淡的生活中寻找一丝快乐；二来也是想以史为鉴，以后在自己的代码里尽可能不要犯同样的错。

当局者迷，会体现在生活中的方方面面，正如写程序的人不知道程序的哪个函数会成为热点一样，我以前上来就是一张火焰图，也没有交代这个怎么得来的，现在准备把这一块补一下。

造场景

火焰图可用来分析程序中的热点函数，找出那些执行耗时比较长的函数(大多数情况下这些函数是性能问题的根源所在)，为后面的代码优化指明方向。

要想讲清楚这个(火焰图)，目前没有想到合适的方法；如若把我走过的弯路和正道都讲一遍，就认识而言也算得上比较全面了。

扯远了，要讲的毕竟不是什么屠龙之术。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. 关于火焰图怎么看

第一步：从下往上看，找到最宽的那条，它就是主要矛盾。如果看不出什么问题，不要留恋，我们要再往上看。

第二步：重复第一步，直到看到了最上面。

相关文章