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

本文涉及的产品
检索分析服务 Elasticsearch 版,2核4GB开发者规格 1个月
简介: Elasticsearch CPU很高的场景很常见,优化读写以及扩容即可解决问题。如果只有一个节点CPU高,那可能的情况就比较多了,节点机器异常?读写不均匀?GC过高?forcemerge?这里描述一个极具迷惑性的case。

背景

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

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

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


问题

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

image.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请求,然后还有日志打印的堆栈。

image.png

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

image.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下,一个节点挂了,另一个承载流量。

image.png

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

image.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~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出多个日志文件。


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

image.png



解释前面的坑

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

image.png

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

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

image.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的知识体系与推理。









相关实践学习
使用阿里云Elasticsearch体验信息检索加速
通过创建登录阿里云Elasticsearch集群,使用DataWorks将MySQL数据同步至Elasticsearch,体验多条件检索效果,简单展示数据同步和信息检索加速的过程和操作。
ElasticSearch 入门精讲
ElasticSearch是一个开源的、基于Lucene的、分布式、高扩展、高实时的搜索与数据分析引擎。根据DB-Engines的排名显示,Elasticsearch是最受欢迎的企业搜索引擎,其次是Apache Solr(也是基于Lucene)。 ElasticSearch的实现原理主要分为以下几个步骤: 用户将数据提交到Elastic Search 数据库中 通过分词控制器去将对应的语句分词,将其权重和分词结果一并存入数据 当用户搜索数据时候,再根据权重将结果排名、打分 将返回结果呈现给用户 Elasticsearch可以用于搜索各种文档。它提供可扩展的搜索,具有接近实时的搜索,并支持多租户。
相关文章
|
7月前
|
Linux Perl
Linux 系统快速分析日志定位故障原因的 10 个方法
在 Linux 系统中,日志是一种非常重要的资源。系统管理员可以通过日志记录的内容来检测系统的运行状况,分析问题,做出相应的调整和优化。由于日志文件数量庞大,内容复杂,因此需要使用一些工具和技术帮助管理员进行快速分析和查找。 本文将介绍 Linux 系统中快速分析日志、定位故障的 10 个方法。
1160 1
|
7月前
|
XML Java API
SpringBoot3.x日志生产最佳实践原来是这样!
SpringBoot3.x日志生产最佳实践原来是这样!
178 0
|
12天前
|
分布式计算 DataWorks 关系型数据库
DataWorks操作报错合集之在DataWorks中设置了一个任务节点的调度时间,并将其发布到生产环境,但到了指定时间(例如17:30)却没有产生运行实例和相关日志如何解决
DataWorks是阿里云提供的一站式大数据开发与治理平台,支持数据集成、数据开发、数据服务、数据质量管理、数据安全管理等全流程数据处理。在使用DataWorks过程中,可能会遇到各种操作报错。以下是一些常见的报错情况及其可能的原因和解决方法。
|
12天前
|
文字识别 运维 Oracle
asm 磁盘故障处理日志
asm 磁盘故障处理日志
28 2
|
12天前
|
Nacos
nacos 2.2.3集群模式下,leader节点,CPU打满
nacos 2.2.3集群模式下,leader节点,CPU打满
43 1
|
12天前
|
Nacos
nacos 2.2.3集群模式下,leader节点,CPU打满,是什么原因?
nacos 2.2.3集群模式下,leader节点,CPU打满,是什么原因?
85 5
|
6月前
|
canal 负载均衡 关系型数据库
Flink CDC如何获得增量binlog,可能是跟canal一样,伪装成从节点获取日志?
Flink CDC如何获得增量binlog,可能是跟canal一样,伪装成从节点获取日志?
104 1
|
10月前
|
弹性计算 人工智能 运维
基于ACK One注册集群实现IDC中K8s集群添加云上CPU/GPU节点
在前一篇文章《基于ACK One注册集群轻松实现云上云下K8s集群统一管理》中,我们注重介绍了注册集群的应用场景,架构实现,安全加固,以及在他云K8s集群和IDC自建K8s集群中使用阿里云容器服务ACK的强大可观测性能力,实现云上云下K8s集群的统一运维管理。本文会重点介绍ACK One注册集群的另一个重要使用场景--云上弹性。概述ACK One注册集群的云上弹性能力针对的场景:业务快速增长:在本
基于ACK One注册集群实现IDC中K8s集群添加云上CPU/GPU节点
|
10月前
|
弹性计算 人工智能 Kubernetes
基于ACK One注册集群实现IDC中K8s集群添加云上CPU/GPU节点
基于ACK One注册集群实现IDC中K8s集群添加云上CPU/GPU节点
|
CDN
CDN诊断工具与日志的作用——如何利用诊断工具进行问题分析(查看定位到的是否是cdn节点)
CDN诊断工具与日志的作用——如何利用诊断工具进行问题分析(查看定位到的是否是cdn节点)自制脑图
139 0
CDN诊断工具与日志的作用——如何利用诊断工具进行问题分析(查看定位到的是否是cdn节点)

热门文章

最新文章