效能優化必備——火焰圖
引言
本文主要介紹火焰圖及使用技巧，學習如何使用火焰圖快速定位軟體的效能卡點。
結合最佳實踐實戰案例，幫助讀者加深刻的理解火焰圖構造及原理，理解 CPU 耗時，定位效能瓶頸。
背景
當前現狀
假設沒有火焰圖，你是怎麼調優程式程式碼的呢？讓我們來捋一下。
1. 功能開關法
想當年我剛工作，還是一個技術小白時，排查問題只能靠玄學，大致能猜出問題可能是由某個功能程式碼導致的，此時的排查手段就是刪除多餘的功能程式碼，然後再執行檢視 CPU 消耗，確定問題。（至今我工作時還會發現一些老人使用如此方法偵錯效能。）
public void demo() {
if (關閉1) {
// 功能1
handle1();
}
if (關閉2) {
// 功能2
handle2();
}
if (開啟3) {
// 功能3
handle3();
}
// 功能4
handle4();
}
此法全靠「經驗」和「運氣」，而且改動了程式碼結構，假設這是一個已經通過測試的整合區程式碼，此時需要修改程式碼功能來偵錯程式是非常危險的一件事，當然有 Git 倉庫可以「一鍵還原」，但是，是人操作，總歸會有失手的時候，且定位效率太低
2. StopWatch 埋點法
當程式出現效能問題時，且不確定是哪一段程式碼導致耗時，可以藉助方法耗時來判斷，此時我們只要在呼叫方法前後追加執行所需耗時紀錄檔，即可判定到底是哪個方法最耗時。
public void demo() {
Stopwatch stopwatch = Stopwatch.createStarted();
handle1();
log.info("method handle1 cost: {} ms",
stopwatch.elapsed(TimeUnit.MILLISECONDS));
handle2();
log.info("method handle2 cost: {} ms",
stopwatch.elapsed(TimeUnit.MILLISECONDS));
handle3();
log.info("method handle3 cost: {} ms",
stopwatch.elapsed(TimeUnit.MILLISECONDS));
handle4();
log.info("method handle4 cost: {} ms",
stopwatch.stop().elapsed(TimeUnit.MILLISECONDS));
}
此法較上一個方法的優勢是，不改變程式碼的邏輯情況下，只是增強了一些觀測點位，由方法的耗時來定位效能瓶頸。但是，假設方法的處理呼叫棧很深，就不得不在子方法中再次埋點，此時判定流程即為：埋點 -> 發版 -> 定位 -> 埋點 -> 發版 -> 定位 -> .......且本質上也是改了程式碼，就有出錯的可能。 心累，不高效！
3. TOP 命令定位熱執行緒
一般企業的軟體服務都是部署在 Linux 作業系統上，有經驗的老手排查效能最方便的辦法就是 top 定位。
top -p pid -H
明顯看到，pid 103 消耗了 40%的 CPU, 找到對應的 stack 執行緒資訊如下（忽略查詢辦法，我假設你已經會了：））：
此時可以得出結論，當前最耗 CPU 的執行緒是寫入磁碟檔案，追查程式碼最終會定位到是因為在高並行場景下打了大量的 INFO 紀錄檔，導致磁碟寫入成為瓶頸。
總結：TOP 命令對於找 CPU 效能瓶頸時很有效的，但是存在如下幾個問題：
- 排名最前的一定是當時最消耗 CPU 的，但不一定是程式效能的誘因。例如因某個 BUG 導致列印了大量 ERROR 紀錄檔，最終 LOG 到磁碟是最消耗 CPU的，但罪魁禍首不是它。
- TOP 註定使你只會關注最高的，等你修復最耗 CPU 的問題後，往往還會遇到別的程式問題導致 CPU 偏高，即一次只能看到一個問題，看不到全貌。
- 文字的表現力非常有限：首先你得對 Linux 及 JVM 命令非常熟悉，其次文字對兩個及以上值做關聯性分析時，就捉襟見肘了，此時就迫切的需要另一種分析工具——圖。
什麼是火焰圖
火焰圖（Flame Graphs），因其形似火焰而得名。
如上就是一個典型的火焰圖，它由各種大小/顏色的方塊組成，每個方塊內部還標識了文字，整個圖片頂部凹凸不平，形似一簇簇「火苗」，因此得名火焰圖。
火焰圖是 SVG 生成，因此可以與使用者互動，滑鼠懸浮在某個方塊時，會詳細展示內部文字。點選後，即會以當前被點選方塊為底向上展開。
特徵
使用火焰圖分析之前，我們得首先了解火焰圖的基本構造
- 每一列代表一個呼叫棧，每一格代表一個被呼叫函數
- 方塊上的字元標識呼叫方法，數位表示當前取樣出現次數
- Y 軸表示呼叫棧深度，X 軸將多個呼叫棧歸併，並首字母排序展示
- X 軸寬度表示取樣資料中出現頻次，即寬度越大，導致效能瓶頸的原因可能就越大（注意：是可能，不是確定）
- 顏色沒什麼意義，隨機分配（可能創始人想讓你看起來更像一個火焰。。）
火焰圖可以做什麼
那此時你已經知道了火焰圖，如何定位軟體問題呢？我們需要一套尋找效能瓶頸的方法論。
可以明確的是 CPU 消耗高的口徑
CPU 消耗高的口徑 = 呼叫棧出現頻率最高的一定是吃 CPU 的
如上我們已經知道了火焰圖的構造，及「物料」含義，此時我們的關注點應該在方形的寬度上，方形的寬度大小代表了該呼叫棧在整個抽樣歷史中出現的次數。次數意味著頻率，即出現次數越多的即可能最消耗 CPU。
但只關注最長的是沒用的，如底部的 root 和中部的方塊都很寬，只能說明這些方法是「入口方法」，即每次發起呼叫都會經過的方法。
我們更應該關注火焰山頂部的"平頂山"（plateaus）出現的次數多，即沒有子呼叫，抽樣出現的頻率高，說明執行方法的時間較長，或者執行頻率太高（如長輪詢），即CPU 大部分執行都分配給了「平頂山」，它才是效能瓶頸的根因。
總結方法論：火焰圖看「平頂山」，山頂的函數可能存在效能問題！
最佳實踐
實踐是檢驗真理的唯一標準！下面我將以一個小的 Demo 來展示如何定位程式效能問題，加深對火焰圖使用的理解。
Demo 程式如下：
public class Demo {
public static void main(String[] args) throws InterruptedException {
ExecutorService executorService = Executors.newFixedThreadPool(20);
while (true) {
executorService.submit(Demo::handle1);
executorService.submit(Demo::handle2);
executorService.submit(Demo::handle3);
executorService.submit(Demo::handle4);
}
}
@SneakyThrows
private static void handle4() {
Thread.sleep(1000);
}
@SneakyThrows
private static void handle2() {
Thread.sleep(50);
}
@SneakyThrows
private static void handle3() {
Thread.sleep(100);
}
@SneakyThrows
private static void handle1() {
Thread.sleep(50);
}
}
程式碼很簡單，當然現實中也不會這麼寫，主要是配合演出。。
主要是開了一個執行緒池，且分別執行四個 task，不同的 task 耗時不一致，此時我們的效能瓶頸在 handle4 這個任務上，在知道結論的前提下，我們比較看火焰圖得出答案的是否符合預期！
1. JVM堆疊資訊拉取
當前我是在自己的 Mac 上執行的程式，idea 執行這一段程式非常便捷，那如何獲取當前執行 main 函數的 PID？
此時需要用到 TOP 命令，上面是個 while 死迴圈，很明顯吃 CPU最厲害，只要找到歸屬 Java 執行緒的最高一個 PID 即為所求。
很明顯得到 COMMAND = java 最高的 PID = 20552
此時執行如下命令獲取堆疊資訊，並寫入 tmp.txt 檔案
jstack -l 20552 > tmp.txt
2. 生成火焰圖
生成火焰圖的工具有很多，我一般會藉助 FastThread，線上分析堆疊，非常方便，同時支援生成火焰圖，方便我們定位問題
開啟官網首頁，選擇剛剛 dump 的堆疊檔案，點選 Analyze，此時只需要等待網站分析好後（正常 3~5 s），即可檢視火焰圖
fastThread 網站分析報告非常豐富，一般的問題我們直接通過它給出的結論基本能定位到問題了，本文暫且無需關注，感興趣的話，後續我會分享，直接拉到 Flame Graph 子標題處
此時明顯能看出4個「平頂山」，且 com.Demo.handle4 寬度最大，com.Demo.handle3 次之，符合預期！
原理剖析
基於上述小 Demo ，我們深入理解下火焰圖的生成原理。
舉個例子，便於你理解，假設我們要觀測一個人在忙些什麼，哪些事最佔用他的時間，會怎麼做？
從時間維度的話，且不考慮成本的話，我肯定安排一個監控攝像頭，全天候 24h，360度監控他，然後再安排人員，逐幀排查，並彙總他所做的事，得出：睡覺 8h，工作8h，玩手機 4h，吃飯2h，其它2h。從而得出結論：睡覺佔用他時間最多。
由上可以總結一套分析流程：
記錄（監控）-> 分析&歸併（逐幀排查） -> Top N -> 得出結論
帶著流程去看我們應該如何排查 CPU 在執行中，哪些事（程序/執行緒）最佔用它的時間呢？
簡單粗暴的方法是每時每刻都記錄執行的方法堆疊，再彙總歸併，得出最耗時的方法棧在哪。此法的問題在於
- 資料量大
- 時間長
其實只要取樣去觀測 CPU 在幹什麼就好了，這是一個概率學問題，如果 CPU 因為執行某個方法耗時，大概率取樣下來，得到的歸併結果也是最多的，雖然有誤差，但是多次統計下，差不了多少的。
同理，dump 下的堆疊，檢視大多數執行緒在幹什麼，依據堆疊內每個方法出現的頻率聚合，出現的頻次最多的就是當前 CPU 分配執行最多的方法。
"pool-1-thread-18" #28 prio=5 os_prio=31 tid=0x00007f9a8d4c0000 nid=0x8d03 sleeping[0x000000030be59000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.Demo.handle2(Demo.java:31)
at com.Demo$$Lambda$2/1277181601.run(Unknown Source)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- <0x00000006c6921ac0> (a java.util.concurrent.ThreadPoolExecutor$Worker)
至於我們的 jstack 資訊如何被處理成火焰圖的格式，社群已經為常見的 dump 格式都提供了工具，stackcollapse-jstack.pl 處理 jstack 輸出。
Example input:
"MyProg" #273 daemon prio=9 os_prio=0 tid=0x00007f273c038800 nid=0xe3c runnable [0x00007f28a30f2000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
...
at java.lang.Thread.run(Thread.java:744)
Example output:
MyProg;java.lang.Thread.run;java.net.SocketInputStream.read;java.net.SocketInputStream.socketRead0 1
總結&展望
火焰圖的介紹到此結束，相信你又多了一種排查問題的手段！
存在即合理，工具之開發重要性而言不必多說，我始終持包容態度面對新事物，它確確實實解決了某些痛點而脫穎而出的。
後續我會介紹更多排查問題的手段，如果你喜歡本文風格，請關注或留言，歡迎討論！