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

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

上篇文章回顧：HBase Replication詳解

?過程記錄

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

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

打印GC日志

-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的情況。

打印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。

打印進入Safepoint慢的線程

-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及Safepoint

GC

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

虛擬機棧中引用的對象
方法區中靜態屬性引用的對象
方法區中常量引用的對象
Native方法棧中引用的對象

Safepoint

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

Counted loop

JVM認為比較短的循環，所以不會放置Safepoint，比如用int作為index的循環。與其對應的是Uncounted loop。

Uncounted loop

JVM會在每次循環回跳之前放置Safepoint，比如用long作為index的循環。所以一個常見的問題是當某個線程跑進了Counted loop時，JVM啟動了GC，然后需要等待這個線程把循環跑完才能進入Safepoint，如果這個循環是個大循環，且循環內執行的比較慢，而且不存在其他函數調用產生其他Safepoint，這時就需要等待該線程跑完循環才能從其他位置進入Safepoint，這就導致了其他線程可能會長時間的STW。

解決問題

UseCountLoopSafepoints

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

修改循環index為long型

上面的Safepoint Timeout日志已經明確指出了，進Safepoint慢的線程是RpcServer里的listener線程，所以在仔細讀了一遍代碼之后，發現其調用到的函數cleanupConnections里有個大循環，具體代碼如下：

/** cleanup connections from connectionList. Choose a random range     
* to scan and also have a limit on the number of the connections     
* that will be cleanedup per run. The criteria for cleanup is the time     
* for which the connection was idle. If 'force' is true then all     
* connections will be looked at for the cleanup.     
* @param force all connections will be looked at for cleanup    
*/
private void cleanupConnections(boolean force) {  if (force || numConnections > thresholdIdleConnections) {    long currentTime = System.currentTimeMillis();    if (!force && (currentTime - lastCleanupRunTime) < cleanupInterval) {      return;    }    int start = 0;    int end = numConnections - 1;    if (!force) {      start = rand.nextInt() % numConnections;      end = rand.nextInt() % numConnections;      int temp;     if (end < start) {        temp = start;  start = end;  end = temp;  } } int i = start; int numNuked =0; while (i <= end) {   Connection c;  synchronized (connectionList) {  try {   c = connectionList.get(i);   } catch (Exception e) {return;} }        if (c.timedOut(currentTime)) { if (LOG.isDebugEnabled()) LOG.debug(getName() + ": disconnecting client " + c.getHostAddress()); closeConnection(c); numNuked++; end--; //noinspection UnusedAssignment c = null;if (!force && numNuked == maxConnectionsToNuke) break;}else i++;} lastCleanupRunTime = System.currentTimeMillis();}
}復制代碼

如注釋所說，它會從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過程可以對大家有所幫助，如有錯誤，歡迎指正。

參考文檔：
https://bugs.openjdk.java.net/browse/JDK-8161147
http://calvin1978.blogcn.com/articles/safepoint.html
https://xhao.io/2018/02/safepoint-1/
https://www.zhihu.com/question/29268019
《深入理解Java虛擬機》周志明著

本文首發于公眾號“小米云技術”，轉載請注明出處，點擊查看原文鏈接。