背景:目前当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。本文就如何排查和解决此问题进行总结。
注:大家可以跳过前面第一和第二步直接从第三步(排查Hbase0.98和1.4.8代码区别)开始阅读,第三步为引发此问题的代码所在。
一、定位问题
首先分别在Kylin3.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进行查询),分别对比Kylin2.0和Kylin3.0的代码,发现虽然两边的代码在写法上有些许不同,但是与HBase通信的最底层的地方并无差别。分别进行了如下尝试:
-
Debug 3.0的服务,意在确定Kylin本身是否会获取region的location或者进行相应的失败重试(实际没有,均是Hbase自身的失败重试);
-
修改3.0的的失败重试机制到0(修改为0后,无论是否移动group均无法正确获取到数据,抛出异常失败重试大于0次,说明配置的HBase失败重试的参数是生效的);
-
修改3.0的失败重试机制到1(修改为1后,移动前可以正确查询并获得结果,移动后无法查询获取结果并抛出异常失败重试大于1次);
-
修改3.0的失败重试机制大于1(移动前后均可以正常查询并获得结果。)
经过上面4种尝试和Debug首先说明HBase失败重试配置是生效的,且移动rgroup后会导致第一次查询失败,需要进行二次尝试,且本身的尝试代码是HBase实现,基本排除是Kylin代码的问题,由于2.0是从其他团队接管过来的集群生产任务居多且暂无测试环境,只能通过硬看代码的方式排查,比较费时。
三、排查Hbase0.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相等或者大于,则永远无法进行失败重试。HBase1.4.8已经修复了此问题duration的计算公式改为(已经花费的时间 + expectedSleep(下次尝试的时间)))。
四、解决问题
- 第一步:修改Kylin
集群所有的HBase客户端hbase.rpc.timeout配置,将其时间由1200000改为120000,重启Kylin集群,再次实验问题解决,可以在不重启Kylin节点的情况查询查询; - 第二步:修复HBase此处超时判断代码逻辑,彻底解决问题。
- 补充一点: 因为一次call请求可能会包含多次RPC,所以rpctimeout的值设置最好小于callTimeout时间.