记一次使用低版本ES Java Client偶尔查询超时问题解决过程
首先说明项目中ES使用版本为2.4版本,ES JavaClient为2.4.4版本。服务器配置为16G、8核。
现象
我们一个地区项目中有一个查询ES的接口莫名其妙的翻页会出现超时,可能翻第一页会出现,可能翻第三页会出现。
排查思路
由于项目没有做任何监控系统,因此唯一的排查思路就是定位到底是哪里执行超时的,在代码中可能发生超时的位置都打了日志并进行临时发布,最后发现是在调用查询ES的时候卡住的(`searchRequestBuilder.execute().actionGet();`),并且没有任何的异常日志,代码执行的过程中很安详的就结束了。<br />到此为止,还没有任何的头绪,
怀疑点
- 查询
ActionRequestBuilder#execute
源码看到使用到了线程池,因此怀疑是机器配置不够,线程不够用了?
public ListenableActionFuture<Response> execute() {
PlainListenableActionFuture<Response> future = new PlainListenableActionFuture<>(threadPool);
execute(future);
return future;
}
因此进入容器内使用top 1命令
查看cpu占用,发现每个cpu占用都很低,因此排除机器配置问题。
- 难道是内存不够用了?JVM一直进行GC,STW了?
使用jstat -gcutil -t 进程jd 1000 1000
查看GC信息,发现GC也正常,Eden、S1、S0、Old区占用都 处于正常范围,FULL GC才3次,Yong GC和Old GC也不是很频繁,因此排除是内存不够导致。
- 再次怀疑是线程问题
使用jstack -l 命令
将线程信息输出出来,查看后,发现有大量的es线程,并且线程状态为WAITING (parking)
,具体线程信息如下
发现线程是阻塞在BaseFuture#get
位置,并且是在调用AdapterActionFuture#actionGet
时发生的,因此跟踪源码,发现BaseFuture内部Sync实现了AQS
,AQS相关文章可查看我之前写的几篇博客,
源码跟踪
BaseFuture#get
实际上是调用的Sync#get
,源码如下:
BaseFuture.Sync#get
V get() throws CancellationException, ExecutionException,
InterruptedException {
// Acquire the shared lock allowing interruption.
//AQS的模板方法,尝试获取共享锁
acquireSharedInterruptibly(-1);
return getValue();
}
AQS#acquireSharedInterruptibly
public final void acquireSharedInterruptibly(int arg)
throws InterruptedException {
if (Thread.interrupted())
throw new InterruptedException();
if (tryAcquireShared(arg) < 0)
doAcquireSharedInterruptibly(arg);
}
看到AQS#acquireSharedInterruptibly
中调用了tryAcquireShared(arg)
判断是否拿到了共享锁,tryAcquireShared(arg)
在Sync
中实现了,代码如下
/*
* Acquisition succeeds if the future is done, otherwise it fails.
*/
@Override
protected int tryAcquireShared(int ignored) {
if (isDone()) {
return 1;
}
return -1;
}
boolean isDone() {
return (getState() & (COMPLETED | CANCELLED)) != 0;
}
getState
是AQS的方法,state默认为0,0与任何数都是0,因此只有当state不为0的时候,才会返回true,那什么时候state才会更改呢,看到这里估计也能猜个八九不离十了,肯定是从ES拿到数据,或者异常后才会修改state,查看Sync看到重写了tryReleaseShared方法
。
@Override
protected boolean tryReleaseShared(int finalState) {
setState(finalState);
return true;
}
原来就是在这里修改state的,查看该方法被哪里调用了,最终是从Sync#complete
调用过去的,根据方法名称我们也可以知道就是完成的时候调用。
private boolean complete(@Nullable V v, @Nullable Throwable t,
int finalState) {
boolean doCompletion = compareAndSetState(RUNNING, COMPLETING);
if (doCompletion) {
// If this thread successfully transitioned to COMPLETING, set the value
// and exception and then release to the final state.
this.value = v;
this.exception = t;
releaseShared(finalState);
} else if (getState() == COMPLETING) {
// If some other thread is currently completing the future, block until
// they are done so we can guarantee completion.
acquireShared(-1);
}
return doCompletion;
}
问题定位
到这里,我们基本就确定了问题所在,我们在调用ES Client去查询的时候,实际上是开启了一个查询线程和一个等待线程,由于查询线程一直没有回调结果,等待线程一直阻塞,导致查询失败。
解决方案
由于用户着急使用,因此采用临时方案,观察到现象为偶发,因此尝试在失败时增加重试机制,发现#actionGet方法
可以设置超时时间,因此更换可设置超时API,并捕获ElasticsearchTimeoutException
,在捕获到异常时进行重试,问题解决。
public T actionGet(long timeout, TimeUnit unit) {
try {
return get(timeout, unit);
} catch (TimeoutException e) {
throw new ElasticsearchTimeoutException(e.getMessage());
} catch (InterruptedException e) {
throw new IllegalStateException("Future got interrupted", e);
} catch (ExecutionException e) {
throw rethrowExecutionException(e);
}
}
至于为何查询线程迟迟不回调,还没有具体的定论,还在继续排查。
本文由博客一文多发平台 OpenWrite 发布!