HeapDump性能社区

性能工具
登录注册
性能文章>如何读懂火焰图？ 实例讲解程序性能优化>

如何读懂火焰图？ 实例讲解程序性能优化转载

DiBob
2年前
755605
导读

软件的性能分析，往往需要查看 CPU 耗时，了解瓶颈在哪里。

火焰图（flame graph）是性能分析的利器。本文介绍它的基本用法。

一、perf 命令

让我们从 perf 命令（performance 的缩写）讲起，它是 Linux 系统原生提供的性能分析工具，会返回 CPU 正在执行的函数名以及调用栈（stack）。

通常，它的执行频率是 99Hz（每秒99次），如果99次都返回同一个函数名，那就说明 CPU 这一秒钟都在执行同一个函数，可能存在性能问题。


$ sudo perf record -F 99 -p 13204 -g -- sleep 30

上面的代码中，perf record表示记录，-F 99表示每秒99次，-p 13204是进程号，即对哪个进程进行分析，-g表示记录调用栈，sleep 30则是持续30秒。

运行后会产生一个庞大的文本文件。如果一台服务器有16个 CPU，每秒抽样99次，持续30秒，就得到 47,520 个调用栈，长达几十万甚至上百万行。

为了便于阅读，perf record命令可以统计每个调用栈出现的百分比，然后从高到低排列。


$ sudo perf report -n --stdio

这个结果还是不易读，所以才有了火焰图。

二、火焰图的含义

火焰图是基于 perf 结果产生的 SVG 图片，用来展示 CPU 的调用栈。

y 轴表示调用栈，每一层都是一个函数。调用栈越深，火焰就越高，顶部就是正在执行的函数，下方都是它的父函数。

x 轴表示抽样数，如果一个函数在 x 轴占据的宽度越宽，就表示它被抽到的次数多，即执行的时间长。注意，x 轴不代表时间，而是所有的调用栈合并后，按字母顺序排列的。

火焰图就是看顶层的哪个函数占据的宽度最大。只要有"平顶"（plateaus），就表示该函数可能存在性能问题。

颜色没有特殊含义，因为火焰图表示的是 CPU 的繁忙程度，所以一般选择暖色调。

三、互动性

火焰图是 SVG 图片，可以与用户互动。

（1）鼠标悬浮

火焰的每一层都会标注函数名，鼠标悬浮时会显示完整的函数名、抽样抽中的次数、占据总抽样次数的百分比。下面是一个例子。


mysqld'JOIN::exec (272,959 samples, 78.34 percent)

（2）点击放大

在某一层点击，火焰图会水平放大，该层会占据所有宽度，显示详细信息。

左上角会同时显示"Reset Zoom"，点击该链接，图片就会恢复原样。

（3）搜索

按下 Ctrl + F 会显示一个搜索框，用户可以输入关键词或正则表达式，所有符合条件的函数名会高亮显示。

四、火焰图示例

下面是一个简化的火焰图例子。

首先，CPU 抽样得到了三个调用栈。


func_c 
func_b 
func_a 
start_thread 

func_d 
func_a 
start_thread 

func_d 
func_a 
start_thread

上面代码中，start_thread是启动线程，调用了func_a。后者又调用了func_b和func_d，而func_b又调用了func_c。

经过合并处理后，得到了下面的结果，即存在两个调用栈，第一个调用栈抽中1次，第二个抽中2次。


start_thread;func_a;func_b;func_c 1 
start_thread;func_a;func_d 2

有了这个调用栈统计，火焰图工具就能生成 SVG 图片。

上面图片中，最顶层的函数g()占用 CPU 时间最多。d()的宽度最大，但是它直接耗用 CPU 的部分很少。b()和c()没有直接消耗 CPU。因此，如果要调查性能问题，首先应该调查g()，其次是i()。

另外，从图中可知a()有两个分支b()和h()，这表明a()里面可能有一个条件语句，而b()分支消耗的 CPU 大大高于h()。

五、局限

两种情况下，无法画出火焰图，需要修正系统行为。

（1）调用栈不完整

当调用栈过深时，某些系统只返回前面的一部分（比如前10层）。

（2）函数名缺失

有些函数没有名字，编译器只用内存地址来表示（比如匿名函数）。

六、Node 应用的火焰图

Node 应用的火焰图就是对 Node 进程进行性能抽样，与其他应用的操作是一样的。


$ perf record -F 99 -p `pgrep -n node` -g -- sleep 30

详细的操作可以看这篇文章。

七、浏览器的火焰图

Chrome 浏览器可以生成页面脚本的火焰图，用来进行 CPU 分析。

打开开发者工具，切换到 Performance 面板。然后，点击"录制"按钮，开始记录数据。这时，可以在页面进行各种操作，然后停止"录制"。

这时，开发者工具会显示一个时间轴。它的下方就是火焰图。

浏览器的火焰图与标准火焰图有两点差异：它是倒置的（即调用栈最顶端的函数在最下方）；x 轴是时间轴，而不是抽样次数。

 

八、Async-profiler介绍

Async-profiler是一个对系统性能影响很少的Java采样分析器，它的实现是基于HotSpot特有的API，通过这些特有的API收集堆栈跟踪和跟踪内存分配，因而其可以和OpenJDK、Oracle JDK和其他基于HotSpot JVM的Java应用在运行时协同工作。

Github项目链接地址：https://github.com/jvm-profiling-tools/async-profiler

Async-profiler可以跟踪以下类型的事件：

  • CPU周期；
  • 硬件和软件性能计数器，如缓存未命中、分支未命中、页面错误、上下文切换等；
  • Java堆中的分配；
  • 满足的锁定尝试，包括Java对象监视器和可重入锁；

支持的平台Linux / x64 / x86 / ARM / AArch64macOS / x64注意：macOS分析仅限于用户空间代码。

 

生成的火焰图，绿色代表用户栈，**代表jvm，红色代表内核；横坐标代表cpu使用的时间。例如：

九、Async-profiler的使用 和 火焰图分析

背景：

目前有一个kafka消费者工程,此工程会消费kafka中的消息，并通过fastjson解析该消息为java实体，然后存入到阻塞队列 BlockingQueue中。另外有若干个线程会从queue中批量拿消息，然后以批量形式写入到 elasticsearch 中。目前在使用中发现存在性能瓶颈，需要定位是该工程对消息转化处理较慢，还是写es操作比较慢。

 

9.1采集cpu profile数据

我们将代码回退到第一次测试的情况,并启动程序，并找到当前进程号(627891)，然后通过如下命令进行采集，并转换为火焰图格式 svg。

1
./profiler.sh -d 15 -i 50ms -o svg -e cpu 627891  > 627891.svg

  • -d N   分析持续时间（以秒为单位）。如果未提供启动，恢复，停止或状态选项，则探查器将运行指定的时间段，然后自动停止。

  • -i N 设置分析间隔(以纳秒或者毫秒等作为单位),默认分析间隔为10ms。

  • -o  转储文件的格式。

等待15s，就会产生结果，生成 627891.svg 文件。vim 627891.svg 并删除第一行，然后下载到本地并使用浏览器打开。

结果如下图，此图俗称火焰图，主要看每个方法的横轴长度，占用横坐标越长的操作，其占用的 cpu 即最长，很直观的。

9.2 性能黑点分析

我们首先发现下图红框内的代码存在严重的性能问题。在append的过程中，获取线程 stack 的过程耗时比较大。从火焰图中分析，耗时占据了接近50%的是，一个logger操作中去拿线程堆栈的过程，那么我们打印的日志的时候，为啥会进行这个操作呢？

首先观察消息日志文件,和一般的日志不同,这里还会打印方法名称，即当前日志时在哪个方法下打印出来的。那么日志框架它是通过线程 stack 去获取到方法名称的，如果配置了 %L,即打印日志所在代码行的情况也是同理。

1
2
3
[2019-10-07 11:50:38 251 INFO ] [PoolDrainDataThreadPool-3] dummy.es.transport.batchAddDocument() - A => {"@timestamp":"2019-10-07T03:50:38.251Z","ipv4":"10.0.49.96:14160;10.0.49.85:14159;10.0.49.85:14160;10.0.49.84:14160;10.0.49.97:14160;10.0.49.96:14159;10.0.49.89:14159;10.0.49.97:14159;10.0.49.86:14159;10.0.49.84:14159;10.0.49.86:14160;10.0.49.89:14160","key":"ss","serviceName":"Redis","spanId":"-496431972509502272","startTs":1570420237,"tag":-1,"timestamp":1570420237329,"traceId":"-2375955836973083482"}
 
[2019-10-07 11:50:38 251 INFO ] [PoolDrainDataThreadPool-3] dummy.es.transport.batchAddDocument() - A => {"@timestamp":"2019-10-07T03:50:38.251Z","ipv4":"10.0.49.96:14160;10.0.49.85:14159;10.0.49.85:14160;10.0.49.84:14160;10.0.49.97:14160;10.0.49.96:14159;10.0.49.89:14159;10.0.49.97:14159;10.0.49.86:14159;10.0.49.84:14159;10.0.49.86:14160;10.0.49.89:14160","key":"ss","serviceName":"Redis","spanId":"6195051521513685066","startTs":1570420237,"tag":-1,"timestamp":1570420237333,"traceId":"-2375955836973083482"}

　　

观察配置的日志格式:

1
2
3
4
5
6
7
8
9
<appender name="dummyEsAppender"
     class="org.apache.log4j.DailyRollingFileAppender">
    <param name="File" value="./logs/dummy-es-transport.log"/>
    <param name="DatePattern" value="'.'yyyy-MM-dd'.log'"/>
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern"
               value="[%d{yyyy-MM-dd HH:mm:ss SSS\} %-5p] [%t] %c.%M() - %m%n"/>
    </layout>
</appender>

注意输出格式中的 %M() 一行，这里意味着在打印日志的时候，需要打印当前日志所在执行的方法，这样看来，这个操作严重影响到了性能。

 

9.3 日志配置规则去除方法名

修改一下日志 append 格式,去掉方法输出，处理速率一下子就达到了7万多。

采用上文中的方法继续使用 async-profiler 生成火焰图，并用浏览器打开。这时候,日志 append 操作所占用的横轴长度显著下降，并且此时速度已经达到了关闭日志append 时的速度，说明修改日志输出格式后能够带来显著的性能提升。

但是观测上图，我们发现了新的性能黑点，如红框所述，我们将其展开,见详细图:

这里主要是一个 toHexString 的操作，竟然占用的cpu资源这么大，这里需要定位。

 

9.4 ObjectId.toHexString 性能优化

查看这一步转换为16进制的字符串的代码如下，我们结合上面的火焰图可以看出来，主要耗时是在 String.format()

这一步操作。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
private String toHexString() {
    StringBuilder buf = new StringBuilder(24);
    byte[] bytes = new byte[12];
    bytes[0] = int3(this.timestamp);
    bytes[1] = int2(this.timestamp);
    bytes[2] = int1(this.timestamp);   
    bytes[3] = int0(this.timestamp);
    bytes[4] = int2(this.machineIdentifier);
    bytes[5] = int1(this.machineIdentifier);
    bytes[6] = int0(this.machineIdentifier);
    bytes[7] = short1(this.processIdentifier);
    bytes[8] = short0(this.processIdentifier);
    bytes[9] = int2(this.counter);
    bytes[10] = int1(this.counter);
    bytes[11] = int0(this.counter); 
 
    for (byte b : bytes) {
        buf.append(String.format("%02x", new Object[]{Integer.valueOf(b & 0xFF)}));
    }
 
    return buf.toString();
 
}

上面这种模式存在比较大的性能问题。byte 数组转换为 16进制字符串性能最好的代码：

1
2
3
4
5
6
7
8
9
10
11
12
private static final char[] HEX_ARRAY = "0123456789ABCDEF".toCharArray();
private String toHexString2() {
      //这一步获取到bytes数组，和上面的操作相同，单独抽离出来。
   byte[] bytes = this.toByteArray();
    char[] hexChars = new char[bytes.length * 2];
    for (int j = 0; j < bytes.length; j++) {
        int v = bytes[j] & 0xFF;
        hexChars[j * 2] = HEX_ARRAY[v >>> 4];
        hexChars[j * 2 + 1] = HEX_ARRAY[v & 0x0F];
    }
    return new String(hexChars);
}

 

9.5 重新测试

修改完耗时的 toHexString() 操作之后，打包上传到服务器，并重新启动程序，此时发现每秒处理速率已经飙升到了 12万。这种使用频繁又耗时的黑点操作解决以后，果然性能能够得到翻倍的提升。

此时日志输出格式已经优化，并且 toHexString(）操作也进行了优化。重新使用 async-profiler 查看一下最新的火焰图信息。

之前的 toHexString() 耗时已经几乎看不到了，但是感觉日志append 的操作横轴还是略长，于是将日志输出关闭来看看极限处理速度。

将日志级别调整为 warn,并启动程序，观测到处理速度已经能够达到 18万/s了，这相当于 toHexString(）优化前的快3倍了。

此时决定再将日志append 模式改为异步模式，然后启动程序，观察，处理速率也能够达到 18万/s。

十、参考链接

（完）

作者：xuxh120；

作者博客地址：https://www.cnblogs.com/xuxh120/

原文链接：https://www.cnblogs.com/xuxh120/p/15990446.html

点赞收藏
分类：
工具
标签：
火焰图
perf
DiBob
请先登录，感受更多精彩内容
快去登录吧，你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流，共同进步
5
0
Lv1
DiBob

徽章

推荐阅读

​HTML代码混淆技术：原理、应用和实现方法详解深度链接（DeepLink）应用场景解析与解决方案使用云函数实现定时签到传统营销与获客痛点对比，真实有效的解决方案来了实用案例：解析工具类App的用户拉新、增长策略如何从抓包文件中分析慢请求
站内搜索
火焰图
Prometheus
jstack
arthas
MAT
XPocket
java
jvm
gc
linux
内存泄漏
内核

本月精选性能专题

本月精选线上案例

本月精选原创好文

HeapDump

有性能问题，上HeapDump性能社区

Copyright © 2019-2024 heapdump.cn 版权所有 浙ICP备17054444号

联系我们

HeapDump性能社区

网媒渠道

堆堆酱

扫码加堆堆酱好友

友情链接

PerfMa官网SegmentFault思否TesterHomeXPocket开源社区DCloud 问答社区稀土掘金博客园W3CTech