如何讀懂火焰圖？+ 例項講解程式效能優化

xuxh120發表於2022-03-10
優化
導讀

軟體的效能分析，往往需要檢視 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。

./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 即最長，很直觀的。

image.png

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萬多。

image.png

採用上文中的方法繼續使用 async-profiler 生成火焰圖，並用瀏覽器開啟。這時候,日誌 append 操作所佔用的橫軸長度顯著下降，並且此時速度已經達到了關閉日誌append 時的速度，說明修改日誌輸出格式後能夠帶來顯著的效能提升。

image.png

但是觀測上圖，我們發現了新的效能黑點，如紅框所述，我們將其展開,見詳細圖:

image.png

這裡主要是一個 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萬。這種使用頻繁又耗時的黑點操作解決以後，果然效能能夠得到翻倍的提升。

image.png

此時日誌輸出格式已經優化，並且 toHexString(）操作也進行了優化。重新使用 async-profiler 檢視一下最新的火焰圖資訊。

image.png

之前的 toHexString() 耗時已經幾乎看不到了，但是感覺日誌append 的操作橫軸還是略長，於是將日誌輸出關閉來看看極限處理速度。

將日誌級別調整為 warn,並啟動程式，觀測到處理速度已經能夠達到 18萬/s了，這相當於 toHexString(）優化前的快3倍了。

image.png

此時決定再將日誌append 模式改為非同步模式，然後啟動程式，觀察，處理速率也能夠達到 18萬/s。

image.png

 

 

十、參考連結

（完）

相關文章