记一次使用低版本ES Java Client偶尔查询超时问题解决过程_java查询es第一次查询经常超时怎么回事

首先说明项目中ES使用版本为2.4版本，ES JavaClient为2.4.4版本。服务器配置为16G、8核。

现象

我们一个地区项目中有一个查询ES的接口莫名其妙的翻页会出现超时，可能翻第一页会出现，可能翻第三页会出现。

排查思路

由于项目没有做任何监控系统，因此唯一的排查思路就是定位到底是哪里执行超时的，在代码中可能发生超时的位置都打了日志并进行临时发布，最后发现是在调用查询ES的时候卡住的（`searchRequestBuilder.execute().actionGet();`），并且没有任何的异常日志，代码执行的过程中很安详的就结束了。<br />到此为止，还没有任何的头绪，
1

怀疑点

• 查询ActionRequestBuilder#execute源码看到使用到了线程池，因此怀疑是机器配置不够，线程不够用了？

public ListenableActionFuture<Response> execute() {
        PlainListenableActionFuture<Response> future = new PlainListenableActionFuture<>(threadPool);
        execute(future);
        return future;
}
1
2
3
4
5

因此进入容器内使用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);
    }
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18

看到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;
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

getState是AQS的方法，state默认为0，0与任何数都是0，因此只有当state不为0的时候，才会返回true，那什么时候state才会更改呢，看到这里估计也能猜个八九不离十了，肯定是从ES拿到数据，或者异常后才会修改state，查看Sync看到重写了tryReleaseShared方法。

@Override
protected boolean tryReleaseShared(int finalState) {
    setState(finalState);
    return true;
}
1
2
3
4
5

原来就是在这里修改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;
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

问题定位

到这里，我们基本就确定了问题所在，我们在调用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);
        }
}
1
2
3
4
5
6
7
8
9
10
11

至于为何查询线程迟迟不回调，还没有具体的定论，还在继续排查。