Elasticsearch-BulkProcessor-死锁分析

最新推荐文章于 2024-04-15 23:18:22 发布

迷路剑客

最新推荐文章于 2024-04-15 23:18:22 发布

阅读量3.7k

点赞数 3

分类专栏： elasticsearch

本文链接：https://blog.csdn.net/baichoufei90/article/details/108468223

版权

elasticsearch 专栏收录该内容

16 篇文章 9 订阅

订阅专栏

Elasticsearch-BulkProcessor-死锁分析

摘要

本文基于ES 6.4.3。主要分析由于在使用BulkProcessor向ES集群提交数据而集群响应异常时，导致的BulkProcessor死锁，而无法继续向BulkProcessor提交新数据，导致整个处理流程卡死的问题。

关于BulkProcessor原理可参考Elasticsearch-BulkProcessor浅析
关于Java线程状态原理可参考Java-多线程-线程状态

1 问题概述

我们程序流程是：

从Kafka消费数据
程序解析数据
处理好后，将数据组装为IndexRequest，使用bulkProcessor.add(indexRequest)，异步批量提交数据到ES

最近Kafka消费延迟监控报警，发现某个topic消费延迟持续增长，消费速率降为0，所以查看了日志，发现最开是出问题的时候报错了：

...
2020-09-05 00:36:21.196 ERROR ElastServiceImpl$2,478 - ElastServiceImpl saveData  failed: null
2020-09-05 00:36:21.196 ERROR ElastServiceImpl$2,479 - bulk failed null msgs
2020-09-05 00:36:26.798 ERROR ElastServiceImpl$2,478 - ElastServiceImpl saveData  failed: null
2020-09-05 00:36:26.798 ERROR ElastServiceImpl$2,479 - bulk failed null msgs
2020-09-05 00:36:28.526 ERROR ElastServiceImpl$2,478 - ElastServiceImpl saveData  failed: null
2020-09-05 00:36:28.526 ERROR ElastServiceImpl$2,479 - bulk failed null msgs
2020-09-05 00:36:28.927 ERROR ElastServiceImpl$2,478 - ElastServiceImpl saveData  failed: null
2020-09-05 00:36:28.927 ERROR ElastServiceImpl$2,479 - bulk failed null msgs

这段日志来源于BulkProcessor

@Override
public void afterBulk(long executionId,
                       BulkRequest request,
                       Throwable failure) {
     logger.error("ElastServiceImpl saveData  failed: " + failure.getMessage());
     logger.error("bulk failed " + failure.getMessage() + " msgs");
 }

而我们的程序消费Kafka后提交offset日志也停在了同一时段：

...
2020-09-05 00:36:19.865 INFO  AbstractKafkaConsumeTask,172 - EsKafkaConsumeTask successfully to commit offset to zookeeper, topic=xxx, consumeId is:1
2020-09-05 00:36:21.192 INFO  AbstractKafkaConsumeTask,172 - EsKafkaConsumeTask successfully to commit offset to zookeeper, topic=xxx, consumeId is:2
2020-09-05 00:36:21.249 INFO  AbstractKafkaConsumeTask,172 - EsKafkaConsumeTask successfully to commit offset to zookeeper, topic=xxx, consumeId is:3

2 问题排查

2.1 日志

消费线程挂了？
否，没有出现相关日志
消费出错？
否，没有出现相关日志
写入ES出错？
否，没有出现相关日志

2.2 top

我先用以下命令看了下有没有占cpu很高的：

top -Hp pid

发现线程占得资源都很平均。

2.3 jstack

也就是说程序只是卡住了，具体卡在哪里，只能用jstack分析。

首先把jstack输出到文件

jstack 29192 > slave.jstack

然后分析该文件.

less slave.jstack

直接搜索BulkProcessor关键字，发现大量相关线程处于BLOCKED阻塞状态，也就是说代码阻塞在synchronized等待对象锁:
在这里插入图片描述
上图中- waiting to lock <0x0000000606b340c8> (a org.elasticsearch.action.bulk.BulkProcessor)字样就是指当前线程在等待对象锁，可以看看该处BulkProcessor#internalAdd代码：

private synchronized void internalAdd(DocWriteRequest request, @Nullable Object payload) {
    ensureOpen();
    bulkRequest.add(request, payload);
    executeIfNeeded();
}

可以看到，该方法是需要获取对象级别的同步锁的。

我们以某个等待的锁编号0x0000000606b340c8来查询，结果如下：
在这里插入图片描述
可以看到，这个elasticsearch[scheduler][T#1]线程已经获取了该对象锁，但现在处于WAITING状态，等待申请 Semaphore，相关代码如下:

而我们知道，BulkProcessor的Flush线程会定时调用这个execute方法，并在响应后释放semaphore。但现在没有被正确释放，说明这个之前的定时调度没有调用回调方法：

@Override
public void onResponse(BulkResponse response) {
    try {
        listener.afterBulk(executionId, bulkRequest, response);
    } finally {
        semaphore.release();
        latch.countDown();
    }
}

@Override
public void onFailure(Exception e) {
    try {
        listener.afterBulk(executionId, bulkRequest, e);
    } finally {
        semaphore.release();
        latch.countDown();
    }
}

而我们Flush线程定时调度相关代码：

scheduler.scheduleWithFixedDelay(flushRunnable, flushInterval, ThreadPool.Names.GENERIC);

那也就造成了无法继续调度，全部在这hang住了。

3 问题总结

因为Flush定时调度线程有两次调度semaphore没有正确被释放，导致后续调度执行到semaphore.acquire()的时候无法获得许可，所以调用了底层的AQS使用的LockSupport.park阻塞，变为WAITING状态。
Flush线程每次run的时候会占用BulkProcessor对象级别的同步锁

@Override
public void run() {
    synchronized (BulkProcessor.this) {
        if (closed) {
            return;
        }
        if (bulkRequest.numberOfActions() == 0) {
            return;
        }
        execute();
    }
}

所以我们的程序消费线程往BulkProcessor插入数据的时候，就无法获取该BulkProcessor对象级同步锁了

private synchronized void internalAdd(DocWriteRequest request, @Nullable Object payload) {
   ensureOpen();
    bulkRequest.add(request, payload);
    executeIfNeeded();
}