HBase實戰：記一次Safepoint導致長時間STW的踩坑之旅

本文記錄了HBase中Safepoint導致長時間STW此問題的解決思路及辦法。

現象：小米有一個比較大的公共離線HBase叢集，使用者很多，每天有大量的MapReduce或Spark離線分析任務在進行訪問，同時有很多其他線上叢集Replication過來的資料寫入，叢集因為讀寫壓力較大，且離線分析任務對延遲不敏感，所以其G1GC的MaxGCPauseMillis設定是500ms。

但是隨著時間的推移，我們發現了一個新的現象，執行緒的STW時間可以到3秒以上，但是實際GC的STW時間卻只有幾百毫秒！

• -XX:+PrintGC

• -XX:+PrintGCDetails

• -XX:+PrintGCApplicationStoppedTime

• -XX:+PrintHeapAtGC

• -XX:+PrintGCDateStamps

• -XX:+PrintAdaptiveSizePolicy

• -XX:+PrintTenuringDistribution

具體的日誌log示例如下：

[Times: user=1.51 sys=0.67, real=0.14 secs]
2019-06-25T12:12:43.376+0800: 3448319.277: Total time for which application threads were stopped: 2.2645818 seconds, Stopping threads took: xxx seconds

-XX:+PrintGCApplicationStoppedTime會打出類似上面的日誌，這個stopped時間是JVM裡所有STW的時間，不止GC。我們遇到的現象就是stopped時間遠大於上面的GC real耗時，比如GC只耗時0.14秒，但是執行緒卻stopped了2秒多。這個時候大機率就是GC時執行緒進入Safepoint耗時過長，所以需要2個新的GC引數來列印出Safepoint的情況。

• -XX:+PrintSafepointStatistics
  

• -XX:PrintSafepointStatisticsCount=1

需要注意的是Safepoint的情況是列印到標準輸出裡的，具體的日誌log示例如下：

vmop    [threads: total initially_running wait_to_block] 
65968.203: ForceAsyncSafepoint [931   1   2]

這部分日誌是時間戳，VM Operation的型別，以及執行緒概況，比如上面就顯示有2個執行緒在等待進入Safepoint：

[time: spin block sync cleanup vmop] page_trap_count
[2255  0  2255 11  0]  1

接下來的這部分日誌是到達Safepoint時的各個階段以及執行操作所花的時間：

spin：因為JVM在決定進入全域性Safepoint的時候，有的執行緒在Safepoint上，而有的執行緒不在Safepoint上，這個階段是等待未在Safepoint上的使用者執行緒進入Safepoint。

block：即使進入Safepoint，使用者執行緒這時候仍然是running狀態，保證使用者不在繼續執行，需要將使用者執行緒阻塞

sync：spin+block的耗時

所以上面的日誌就是說，有2個執行緒進入Safepoint特別慢，其他執行緒等待這2個執行緒進入Safepoint等待了2255ms。

• -XX:+SafepointTimeout

• -XX:SafepointTimeoutDelay=2000

這兩個引數的意思是當有執行緒進入Safepoint超過2000毫秒時，會認為進入Safepoint超時了，這時會打出來哪些執行緒沒有進入Safepoint，具體日誌如下：

# SafepointSynchronize::begin: Timeout detected:
# SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.
# SafepointSynchronize::begin: Threads which did not reach the safepoint:
# "RpcServer.listener,port=24600" 
#32 daemon prio=5 os_prio=0 tid=0x00007f4c14b22840 nid=0xa621 runnable [0x0000000000000000]java.lang.Thread.State: RUNNABLE
# SafepointSynchronize::begin: (End of list)

從上面的日誌可以看出來是RpcServer.listener進入Safepoint耗時過長，那麼該如何解決這個問題呢？這就需要了解一點GC和Safepoint的背景知識了。

GC（Garabage Collection）：垃圾回收，是Java這種自動記憶體管理語言中的關鍵技術。GC要解決的三個關鍵問題是：哪些記憶體可以回收？什麼時候回收？以及如何回收？對於哪些記憶體可以回收，常見的有引用計數演算法和可達性分析演算法來判斷物件是否存活。可達性分析演算法的基本思路是從GC Roots出發向下搜尋，搜尋走過的路徑稱為引用鏈，當一個物件到GC Roots沒有任何引用鏈相連時，則稱該物件不可達，也就是說可以回收了。常見的GC Roots物件有：

• 虛擬機器棧中引用的物件

• 方法區中靜態屬性引用的物件

• 方法區中常量引用的物件

• Native方法棧中引用的物件

Java虛擬機器HotSpot的實現中，使用一組稱為OopMap的資料結構來存放物件引用，從而可以快速且準確的完成GC Root掃描。但程式執行的過程中，引用關係隨時都可能發生變化，而HotSpot虛擬機器只會在特殊的指令位置才會生成OopMap來記錄引用關係，這些位置便被稱為Safepoint。換句話說，就是在Safepoint這個點上，虛擬機器對於呼叫棧、暫存器等一些重要的資料區域裡什麼地方包含了什麼引用是十分清楚的，這個時候是可以很快完成GC Roots的掃描和可達性分析的。HotSpot會在所有方法的臨返回之前，以及所有Uncounted loop的迴圈回跳之前放置Safepoint。當需要GC時候，虛擬機器會首先設定一個標誌，然後等待所有執行緒進入Safepoint，但是不同執行緒進入Safepoint的時間點不一樣，先進入Safepoint的執行緒需要等待其他執行緒全部進入Safepoint，所以Safepoint是會導致STW的。

-XX:+UseCountedLoopSafepoints這個引數會強制在Counted loop迴圈回跳之前插入Safepoint，也就是說即使迴圈比較短，JVM也會幫忙插入Safepoint了，用於防止大迴圈執行時間過長導致進入Safepoint卡住的問題。但是這個引數在JDK8上是有Bug的，可能會導致JVM Crash，而且是到JDK9才修復的，具體參考JDK-8161147。鑑於我們使用的是OpenJDK8，所以只能放棄該方案。

上面的Safepoint Timeout日誌已經明確指出了，進Safepoint慢的執行緒是RpcServer裡的listener執行緒，所以在仔細讀了一遍程式碼之後，發現其呼叫到的函式cleanupConnections裡有個大迴圈，具體程式碼如下：

如註釋所說，它會從connectionList中隨機選擇一個區間，然後遍歷這個區間內的connection，並清理掉其中已經timeout的connection。但是，connectionList有可能很大，因為出問題的叢集是個離線叢集，會有多個MR/Spark Job來進行訪問，而每個Job又會同時起多個Mapper/Reducer/Executer來進行訪問，其每一個都是一個HBase Client，而Client為了效能考慮，預設連同一個RegionServer的connection數使用了配置4，這就導致connectionList裡面可能存在大量的從client連線過來的connection。更為關鍵的是，這裡迴圈的index是int型別，所以這是一個Counted loop，JVM不會在每次迴圈回跳的時候插入Safepoint。當GC發生時，如果RpcServer的listener執行緒剛好執行到該函式里的迴圈內部時，則必須等待迴圈跑完才能進入Safepoint，而此時其他執行緒也必須一起等著，所以從現象上看就是長時間的STW。    

Debug的過程很曲折，但問題解決起來其實很簡單，就是把這裡的迴圈index從int型別改為long型即可，這樣JVM會在每次迴圈回跳前插入Safepoint，即使GC時候執行到了迴圈內部，也只需執行到單次迴圈體結束便可以進入Safepoint，無需等待整個迴圈跑完。具體程式碼修改如下：

至此，問題得到解決。

最後，本文重點不是介紹Safepoint原理，主要是對一次線上真實Case的的踩坑記錄，希望文中的JVM引數配置和Debug過程可以對大家有所幫助，如有錯誤，歡迎指正。