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

時間 2019-11-06

標籤 hbase 實戰一次 safepoint 致使長時間 stw 之旅欄目 Hadoop 简体版

原文原文鏈接

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

過程記錄

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

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

打印GC日誌

-XX:+PrintGC數據結構
-XX:+PrintGCDetailsapp
-XX:+PrintGCApplicationStoppedTimedom
-XX:+PrintHeapAtGC函數
-XX:+PrintGCDateStampsoop
-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虛擬機》周志明著

本文首發於公衆號「小米雲技術」，轉載請註明出處，點擊查看原文連接。