问题排查 | Kylin 2.0-HBase 0.98 重启

背景：目前当 HBase 添加、删除节点，重启、移动 rgroup，或者 HBase table 移动 region server 等操作后，均需要 Kylin 的所有节点重启，理论上这些操作可以对上层应用透明，或者只有短暂的不可用后自行恢复。但是，目前咱们有 8 套 Kylin 集群均需要在 HBase 变动后进行 Kylin 重启，才可以继续提供相应的服务，对上层服务影响较大，HBase 的变更也会变得复杂。但是咱们提供的 Kylin 3.0 版本却没有此问题，Kylin 3.0 版本对应的 HBase 版本是 1.4.8 版本，有问题的八套 Kylin 集群的版本为 2.0，HBase 版本为 0.98。本文就如何排查和解决此问题进行总结。

注：大家可以跳过前面第一和第二步直接从第三步（排查 HBase 0.98 和 1.4.8 代码区别）开始阅读，第三步为引发此问题的代码所在。

一、定位问题

首先分别在 Kylin 3.0 和 2.0 集群上找到一个 cube对应的 HBase table 表，然后移动对应 table 的 rgroup 即换存储的机器。发现 Kylin 3.0 仍然可以查询，但是 2.0 无法在获取到结果，Kylin 2.0 抛出的异常如下：

2019-07-18 16:43:59,148 ERROR [http-bio-8088-exec-438] controller.BasicController:54 :
org.apache.kylin.rest.exception.InternalErrorException: Error while executing SQL "select * from DPS_DATA_CENTER.SYS_PROBE limit 2": java.net.SocketTimeoutException: callTimeout=1200000, callDuration=1200108: row '' on table 'DPS_DATA_CENTER:KYLIN_N59AHNZIMB' at region=DPS_DATA_CENTER:KYLIN_N59AHNZIMB,,1542085088058.6b1f069c03aa1cfc6649b6762bc79451., hostname=bigdata-dnn-hbase33.gs.com,60020,1551705541907, seqNum=3
        at org.apache.kylin.rest.service.QueryService.doQueryWithCache(QueryService.java:402)
        at org.apache.kylin.rest.controller.QueryController.query(QueryController.java:71)
        at sun.reflect.GeneratedMethodAccessor201.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221)
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136)
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:743)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:672)
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:82)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:933)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:867)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:951)
        at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:853)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:650)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:827)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

通过错误可以看到查询此表的某个 region 时还是去之前的机器（bigdata-dnn-hbase33.gs.com）查询，理论上这个查询是会自动失败重试到新机器查询的，但是 Kylin 的这个错误显然还是到了之前的节点查询。根据之前的经验和其他 HBase 的用户并无此问题，大致猜想可能是没有配置 HBase 失败重试(实际后来排查配置了此选项且配置的 35 次)或 Kylin 调用代码有问题，所以有了下面 2.0 代码和 3.0 代码的对比。

二、排查 Kylin 2.0 和 3.0 代码区别

首先定位查询服务的 Kylin 代码逻辑（主要是 Kylin 通过 rpc 调用对应的 HBase table 所在节点的 coprocessor 进行查询），分别对比 Kylin 2.0 和 Kylin 3.0 的代码，发现虽然两边的代码在写法上有些许不同，但是与 HBase 通信的最底层的地方并无差别。分别进行了如下尝试：

1. Debug 3.0 的服务，意在确定 Kylin 本身是否会获取 region 的 location 或者进行相应的失败重试（实际没有，均是 HBase 自身的失败重试）；
   
2. 修改 3.0 的失败重试机制到 0（修改为 0 后，无论是否移动 group 均无法正确获取到数据，抛出异常失败重试大于 0 次，说明配置的 HBase 失败重试的参数是生效的）；
   
3. 修改 3.0 的失败重试机制到 1（修改为 1 后，移动前可以正确查询并获得结果，移动后无法查询获取结果并抛出异常失败重试大于 1 次）；
   
4. 修改 3.0 的失败重试机制大于 1（移动前后均可以正常查询并获得结果。）

经过上面 4 种尝试和 Debug，首先说明 HBase 失败重试配置是生效的，且移动 rgroup 后会导致第一次查询失败，需要进行二次尝试,且本身的尝试代码是 HBase 实现，基本排除是 Kylin 代码的问题，由于 2.0 是从其他团队接管过来的集群生产任务居多且暂无测试环境，只能通过硬看代码的方式排查，比较费时。

三、排查 HBase 0.98 和 1.4.8 代码区别（真正问题原因）

之前所有的猜想（配置或 Kylin 两个版本代码调用区别导致）基本排除掉，只能重新来看 2.0 查询抛出的异常。很奇怪 2.0 抛出的异常为 java.net.SocketTimeoutException 异常，但是 3.0 失败重试机制到达后抛出的是“Call exception, tries=”异常，决定好好看下 HBase retry 的代码。果然在 HBase 的 RpcRetryingCaller 类发现了 java.net.SocketTimeoutException 抛出的原因。HBase 在 retry 的时候有两个逻辑判断是否继续重试：

1. 重试次数如果达到配置的次数则不再重试，并抛出“Call exception, tries=”等关键字的异常代码（3.0 中的尝试也说明了这点）；
2. 重试过程中整个时长如果大于了配置的超时时长也会不再重试，并抛出“java.net.SocketTimeoutException”等关键字的异常代码（2.0 中正是这个异常）。

HBase 有问题的代码也正是这个超时异常的代码。接下来咱们看下这块儿失败重试的具体代码：

/**
 * Retries if invocation fails.
 * @param callTimeout Timeout for this call
 * @param callable The {@link RetryingCallable} to run.
 * @return an object of type T
 * @throws IOException if a remote or network exception occurs
 * @throws RuntimeException other unspecified error
 */
@edu.umd.cs.findbugs.annotations.SuppressWarnings
    (value = "SWL_SLEEP_WITH_LOCK_HELD", justification = "na")
public synchronized T callWithRetries(RetryingCallable<T> callable, int callTimeout)
throws IOException, RuntimeException {
  this.callTimeout = callTimeout;
  List<RetriesExhaustedException.ThrowableWithExtraContext> exceptions =
    new ArrayList<RetriesExhaustedException.ThrowableWithExtraContext>();
  this.globalStartTime = EnvironmentEdgeManager.currentTimeMillis();
  for (int tries = 0;; tries++) {
    long expectedSleep = 0;
    try {
      beforeCall();
      callable.prepare(tries != 0); // if called with false, check table status on ZK
      return callable.call();
    } catch (Throwable t) {
      if (tries > startLogErrorsCnt) {
        LOG.info("Call exception, tries=" + tries + ", retries=" + retries + ", retryTime=" +
            (EnvironmentEdgeManager.currentTimeMillis() - this.globalStartTime) + "ms, msg="
            + callable.getExceptionMessageAdditionalDetail());
      }
      // translateException throws exception when should not retry: i.e. when request is bad.
      t = translateException(t);
      callable.throwable(t, retries != 1);
      RetriesExhaustedException.ThrowableWithExtraContext qt =
          new RetriesExhaustedException.ThrowableWithExtraContext(t,
              EnvironmentEdgeManager.currentTimeMillis(), toString());
      exceptions.add(qt);
      ExceptionUtil.rethrowIfInterrupt(t);
      if (tries >= retries - 1) {
        throw new RetriesExhaustedException(tries, exceptions);
      }
      // If the server is dead, we need to wait a little before retrying, to give
      //  a chance to the regions to be
      // get right pause time, start by RETRY_BACKOFF[0] * pause
      expectedSleep = callable.sleep(pause, tries);
 
      // If, after the planned sleep, there won't be enough time left, we stop now.
      long duration = singleCallDuration(expectedSleep);//有问题的代码，实现逻辑可以看singleCallDuration方法的源码
      if (duration > this.callTimeout) {//由于singleCallDuration实现的问题+用户的配置，duration永远都会大于callTimeout，所以无法真正进行失败重试
        String msg = "callTimeout=" + this.callTimeout + ", callDuration=" + duration +
            ": " + callable.getExceptionMessageAdditionalDetail();
        throw (SocketTimeoutException)(new SocketTimeoutException(msg).initCause(t));
      }
    } finally {
      afterCall();
    }
    try {
      Thread.sleep(expectedSleep);
    } catch (InterruptedException e) {
      throw new InterruptedIOException("Interrupted after " + tries + " tries  on " + retries);
    }
  }
}

singleCallDuration 方法源码：

/**
 * @param expectedSleep
 * @return Calculate how long a single call took
 */
private long singleCallDuration(final long expectedSleep) {
/*
*此处代码原本的意思应该是要获取一共花费了多少时间，即从开始执行到现在 + 下一次失败重试需要的时间 ，但是此处他还加了rpcTimeout的时间（这个值用户
*在hbase-site.xml中可以配置，且正好2.0的8套Kylin集群对应的HBase客户端配置了此值为1200000）。Hbase 3.0此处的代码是没有加rpcTimeout的时间的，
*理论也不应该加
*
*/
  int timeout = rpcTimeout > 0 ? rpcTimeout : MIN_RPC_TIMEOUT;
  return (EnvironmentEdgeManager.currentTimeMillis() - this.globalStartTime)
    + timeout + expectedSleep;
}

总结下原因：

HBase 失败重试的时候判断是否超时，首先会获取从执行到下次失败重试一共要花费的时间（duration），但是这块儿在计算 duration 的逻辑有问题(已经花费的时间+ rpctimeout（1200000） + expectedSleep（下次尝试的时间）)），然后在用 duration 时间与 callTimeout（默认1200000，正好与配置的 rpctimeout 相等）比较，看 duration 计算公式知道，duration 如果配置的时间和 callTimeout 相等或者大于，则永远无法进行失败重试。HBase 1.4.8 已经修复了此问题 duration 的计算公式改为（已经花费的时间 + expectedSleep（下次尝试的时间））。

四、解决问题

第一步：修改 Kylin

集群所有的 HBase 客户端 hbase.rpc.timeout 配置，将其时间由 1200000 改为 120000，重启 Kylin 集群，再次实验问题解决，可以在不重启 Kylin 节点的情况查询查询；

第二步：修复 HBase 此处超时判断代码逻辑，彻底解决问题。

补充一点：因为一次 call 请求可能会包含多次 RPC，所以 rpctimeout 的值设置最好小于 callTimeout 时间。

作者介绍：王小静，滴滴大数据架构专家工程师，目前是滴滴 Kylin 引擎的负责人。曾负责架构和运营了滴滴数据中台相关系统——大数据任务调度系统、大数据资产管理、大数据权限管理、数据导入、数据开发等，具有丰富的大数据中台建设和 OLAP 相关经验。