Z.S.K.'s Records

记一次排查ES FGC导致的集群宕机异常

有一个私有云环境的运维同事反应项目中的ES集群无法查询, 由于是私有云环境, 没有直接运维权限, 所以没有接收到一线报警, 远程登录上去后发现ES集群已经宕机了, 这次的排查过程也发现了几个比较容易忽视的细节, 在此记录一下,比较有意思.

集群状态

ES集群为3节点.

首先肯定是查看集群状态

1
2
curl 'http://localhost:9200/_cluster/health?pretty' -u xxx:yyy
#发现状态为Red

查看节点状态

1
2
curl 'http://localhost:9200/_cat/node?v' -u xxx:yyy
#节点数正常

查看各节点使用的磁盘情况

1
2
curl -XGET 'localhost:9200/_cat/allocation?v&pretty' -u xxx:yyy
#未发现异常

集群日志

登录一个ES节点查看日志,发现以下报错,查看其它2个节点,情况相同

从日志来看, 可以发现几个问题:

  • Full GC很频繁, 而且时间也非常的长
  • 每次GC完之后所能释放的内存非常有限

到这,其它原因已经很明朗, 内存不够导致的full gc 频繁,但是又不能释放太多的空间,又导致full gc的恶意循环

如果大家对gc的日志不很了解的话, 这里解释下上面日志的各个字段含义, 假如有以下一条gc日志

1
[2018-06-30T17:57:29,020][INFO ][o.e.m.j.JvmGcMonitorService] [qoo--ES] [gc][old][228385][160772] duration [5s], collections [1]/[5.1s], total [5s]/[4.4d], memory [945.4mb]->[958.5mb]/[1007.3mb], all_pools {[young] [87.8mb]->[100.9mb]/[133.1mb]}{[survivor] [0b]->[0b]/[16.6mb]}{[old] [857.6mb]->[857.6mb]/[857.6mb]}
  • gc old 本次是 old GC 这是第228385次 GC 检查][从 JVM 启动至今发生的第 160772次 G]
  • duration [本次检查到的 GC 总耗时 5 秒,可能是多次的加和
  • collections [从上次检查至今总共发生1次GC]/[从上次检查至今已过去 5.1 秒],
  • total [本次检查到的 GC 总耗时为 5 秒]/[从 JVM 启动至今发生的 GC 总耗时为 4.4 天],
  • memory [ GC 前 Heap memory 空间]->[GC 后 Heap memory 空间]/[Heap memory 总空间],
  • all_pools(分代部分的详情) {young 区][GC 前 Memory ]->[GC后 Memory]/[young区 Memory 总大小] }
  • survivor [GC 前 Memory ]->[GC后 Memory]/[Memory 总大小] }{old 区[GC 前 Memory ]->[GC后 Memory]/[old区 Memory 总大小] }

那为何会内存不足呢, 想起前几天服务拓展,添加收集了几个服务的日志, 日志量不算小, 而且这3个ES节点所在的机器内存只分配了8个G, 显然, 加完这几个日志之后内存不够用了.

Index Mapping

而且,从日志中, 还发现几处很诡异的日志

红框中的错误: object mapping for [msg] tried to pasrse field [msg] as object, but found a concrete

翻译过来就是说, 日志中的msg这个字段的类型匹配不上, ES尽力把它解析为object类型,但是它却是个确切的值.

就好比你在python中定义了一个字典, 但是你给它赋值一个整形, 这确定要报错.

但是这个mapping是从何而来的呢.

经过网上搜索一翻, 终于明白:

ES中为了加强性能,对于索引中的第一条数据, ES会默认(可设置)按照这条数据建立index mapping, 相当于是一个索引模板, 好比是mysql中表的定义一个概念, 后续这个索引中的所有日志都按照该模板进行解析

后来经过查看源码, 我们发现,出现上图中的问题是因为代码中的日志打印不规范, 有一个地方如果抛出异常时,打印的是一个单一字符串, 而正常情况下打印的是一个json, 所以当第一条正常的日志传递给ES时,ES建立的索引 模板记录这个字段为object类型(可以类比为python中的字典, 本身是可以新增元素的), 当应用抛出异常时,日志中又传递了一个单一字符串, 但是索引模板已经记录为object类型,所以无法匹配, 这就是问题所在

Fix Bug

从3个方面解决上面的问题

首先是修复代码中日志不规范问题, 这个充暴露了code view不严谨.

第2个是加大ES的内存,毕竟日志量确实是上来了, 从8G添加到12G

第3个是优化ES的gc问题, ES中有个逻辑是:默认情况下,主节点每30秒会去检查其他节点的状态,如果任何节点的垃圾回收时间超过30秒(Garbage collection duration)且在重复次数内都超时,则会导致主节点任务该节点脱离集群, 节点脱离集群后会引起分片的rebalance

这个机制让ES节点频繁的脱离集群,而又引起整个集群的rebalance,ES本身的内存就不够,rebalance更是雪上加霜, 如此往复就导致整个ES集群宕机.

可修改主节点的检查时间及重复次数,让其它节点有充分的时间进行full gc.

在ES的配置文件中添加以下配置:

1
2
discovery.zen.fd.ping_timeout: 300s
discovery.zen.fd.ping_retriES: 10

这样, 达到这两个条件时才能触发节点脱离集群

至此, 依次重启ES节点, 问题圆满解决.

参考文章:

转载请注明出处https://izsk.me

Z.S.K. wechat
Scan Me To Read on Phone
I know you won't do this,but what if you did?