不要急,总有办法的

一个迷惑性很高的生产故障-Elasticsearch日志rotate导致节点CPU激增

Elasticsearch | 作者 zmc | 发布于2022年07月23日 | | 阅读数:406

背景

Elasticsearch CPU很高的场景很常见,优化读写以及扩容即可解决问题。

如果只有一个节点CPU高,那可能的情况就比较多了,节点机器异常?读写不均匀?GC过高?forcemerge?

这里描述一个极具迷惑性的case。

问题

收到用户报障碍,突然有写入被reject,并且有一个节点的CPU突然增高。

zmccc1.png

分析、验证与结论

1.常用套路,先大致了解集群、索引。

集群层面:6.8.5 版本,18个节点(冷热分离)

索引层面:近3000个索引,大多数小索引(mb、1~10gb级别),template(设置1主分片、1副本分片)

用户行为:写多读少的OLAP场景

2.检查节点(pod)监控、宿主机监控、ES集群监控。没有很明显的异常行为。只能观测到异常节点CPU高、出现reject。用户的读写流量也没有观测到明显变化。

3.集群GC、merge等行为都很正常,并且只有一个节点CPU高(刚好用户索引都是1主1副),开始认为和热点相关。可能是某个索引的读写导致了节点CPU的上升。

4.使用 GET _nodes/hot_threads 查看CPU使用情况,果然抓到了异常节点占用CPU的主要是 write 线程。

5.由于hot_threads只能抓取瞬时的数据,不一定准确。准备进入容器,使用arthas工具抓取perf信息(arthas是阿里的开源工具、已经被我们集成到ES镜像里)。

通过arthas简要的获取热点线程:可以看到主要是write线程在执行bulk请求,然后还有日志打印的堆栈。

zmcccc2.png

继续抓取2min内的统计信息:可以看到主要是search在使用CPU。和之前获取的信息不符。

zmccc3.pg_.png

6.分析到底是读还是写影响的CPU。

a.如果是写热点导致,应该会有2个节点CPU高;

b.写入一般很难长时间打高CPU,而一个拉全量/大量数据的大请求很可能拉高CPU,由于index设置1主1副本,刚好可以解释只有一个节点CPU高;

c.考虑到抓取的数据perf结果,2min内的抓取结果比瞬时的可信;

综合来看,大查询导致的CPU高的概率很大。

7.继续走排障流程,查看日志信息

看到异常节点日志里大多都是这类异常。

elasticsearch org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to stream /usr/share/elasticsearch/logs/e100024741.log org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to stream....

由于节点已经跑了很长时间,log盘写满也是有可能的,而且不太可能瞬间拉高CPU,暂时忽略。

8.进一步验证,将异常节点重启。

果然异常节点CPU下去了,另一个节点CPU起来了,进一步证明了是查询导致的,1主1副的case下,一个节点挂了,另一个承载流量。

zmccc4.png

继续观察异常节点的流量:outgoing的流量比较高,又进一步佐证了是查询带来的异常。

zmccc5.png

继续查看IO,write/read都相对比较高。

9.考虑到查询无法被阻断、且该节点异常带来的影响并不大,准备等“拉数据的大请求”执行完毕自动恢复。

10.开始关注其他问题。等待一段时间,发现依然没有恢复,且CPU完全没有下降的趋势。考虑到一个大请求不会执行这么长时间,如果多个大请求,至少reject、cpu曲线会有些波动,不会如此稳定。准备继续排查。再次执行多次hot_thread API,依然有很多次都只抓到了write线程占用大量CPU,如果大请求存在,不会一直抓不到search请求。

11.考虑其他思路。找到重启前异常节点和重启异常节点后才异常的节点共有的index(互为主备),在众多index中发现了一个较大的index(800G)。看了下文档数:2147483519,至此,找到了问题的答案。

12.结论:使用了同一template的大量索引(1 primary 1 replica),存在一个index写了大量doc数,超过了lucene的最大限制(integer的最大值),疯狂报错reject,并且记录大量异常日志,日志不断的rotate、清理造成了CPU的大幅上升。

仔细检查异常开始时间节点的日志,可以发现如下异常信息:

[2022-07-22T12:00:36,376][DEBUG][o.e.a.b.TransportShardBulkAction] [e100024741-es-default-1][cp0006014_2022_07][0] failed to execute bulk item (index) index {[cp0006014_2022_07][event_cp][Ir_HJYIBi3-VIQ2V8GIT], source[{"rowkey":"fff5e48f-13d9-4f68-b9c9-8cfc1f0fefa3","column01":"BatchValidateRecevieCouponRealTime","column02":"1","column03":"289358095","column04":"100009826","column05":"nkryj","column06":"32001052810269459246","column08":"fff5e48f-13d9-4f68-b9c9-8cfc1f0fefa3","column09":"[34m~L[34m~A34m~O~Q34m~H[34m~D34m| "column11":"2022-07-22 20:00:29.703","column12":"1","column20":"0","datachangelasttime":1658491229707,"rules":[],"rulesh":[],"scenes":[]}]}
java.lang.IllegalArgumentException: number of documents in the index cannot exceed 2147483519
        at org.apache.lucene.index.DocumentsWriterPerThread.reserveOneDoc(DocumentsWriterPerThread.java:226) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
        at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:235) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
        at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:494) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
        at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1616) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1235) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
        at org.elasticsearch.index.engine.InternalEngine.addDocs(InternalEngine.java:1175) ~[elasticsearch-6.8.5.jar:6.8.5]
        at org.elasticsearch.index.engine.InternalEngine.indexIntoLucene(InternalEngine.java:1120) ~[elasticsearch-6.8.5.jar:6.8.5]

进一步验证:进入容器清理日志文件,会立刻生成并rotate出多个日志文件。

最终处理:清理掉异常索引立刻恢复正常:

zmccc6.png

解释前面的坑

1.arthas采集2min内的CPU信息,得到的search结论是正确的,该集群确实存在search大请求。虽然频率不高,但是采集到的概率很大。

zmccc7.png

2.异常节点的out流量很大。这个逻辑也是正确的,只是并不是导致异常的根本原因。

确实有拉数据的请求存在;节点存在大量索引的分片,无法确认流量来源是否是其他index;该异常情况下用户收到异常ack之后会有重试,影响到流量的统计。

zmccc8.pnng_.png

3.重启后另一个节点CPU就开始激增,是因为副本分片成为了主分片,然后开始reject,并疯狂打印日志、进行rotate和清理。

4.为什么只有一个节点CPU高。写入流程是主分片写入成功后,异步转发请求给所有副本(此处只有1),由于主分片写入失败,直接异常,副本也就不会受到影响。

思考

1.经验流大多情况有效,有时却不可取。时刻根据事实排障,避免先入为主。

2.相似的现象以及采集排障数据的巧合进入思维误区,集群业务复杂度增加了排障难度:

大量的日志难以查找(被AppenderLoggingException淹没),且都被判定为和本次异常无关,如 bulk reject 被认为是CPU高的场景下正常的表现,AppenderLoggingException 被认为无法快速消耗CPU,number of documents in the index cannot exceed 2147483519 刚看到时也被认为无法导致CPU增高(仅仅是无法写入);

index太多,无法从单个index层面获取更多信息。(没有明确目标的情况下难以发现那一个异常index)。

3.arthas write线程的堆栈信息中有体现,bulk之后就在打印日志,这两点之间的关联被忽略。

4.优化方向:需要更细粒度的监控和巡检能力,快速发现异常index可大大加快排障进程,不再强依赖OPS的知识体系与推理。


[尊重社区原创,转载请保留或注明出处]
本文地址:http://elasticsearch.cn/article/14674


0 个评论

要回复文章请先登录注册