如何讀懂火焰圖？+ 實例講解程序性能優化

火焰圖（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。

./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,即打印日志所在代碼行的情況也是同理。

[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"}

觀察配置的日志格式:

<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()

這一步操作。

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進制字符串性能最好的代碼：

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。

十、參考鏈接

火焰圖的介紹論文
火焰圖官方主頁
火焰圖生成工具
https://www.ruanyifeng.com/blog/2017/09/flame-graph.html
https://www.cnblogs.com/leihuazhe/p/11630466.html

（完）