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虚拟机》周志明著

本文首发于公众号“小米云技术”，转载请注明出处，点击查看原文连接。