有一个私有云环境的运维同事反应项目中的ES集群无法查询, 由于是私有云环境, 没有直接运维权限, 所以没有接收到一线报警, 远程登录上去后发现ES集群已经宕机了, 这次的排查过程也发现了几个比较容易忽视的细节, 在此记录一下,比较有意思.
集群状态
ES集群为3节点.
首先肯定是查看集群状态
1 | curl 'http://localhost:9200/_cluster/health?pretty' -u xxx:yyy |
查看节点状态
1 | curl 'http://localhost:9200/_cat/node?v' -u xxx:yyy |
查看各节点使用的磁盘情况
1 | 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 | discovery.zen.fd.ping_timeout: 300s |
这样, 达到这两个条件时才能触发节点脱离集群
至此, 依次重启ES节点, 问题圆满解决.
