【Elasticsearch】你看懂ElasticsearchLog中的GC日志了吗？

1.概述

转载&＃xff1a;https://elasticsearch.cn/article/812

如果你关注过 elasticsearch 的日志&＃xff0c;可能会看到如下类似的内容&＃xff1a;

[2018-06-30T17:57:23,848][WARN ][o.e.m.j.JvmGcMonitorService] [qoo--eS] [gc][228384] overhead, spent [2.2s] collecting in the last [2.3s][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]关键词你也猜到了这是与 GC 相关的日志&＃xff0c;那么你了解每一部分的含义吗&＃xff1f;如果不了解&＃xff0c;你可以继续往下看了。

我们先从最简单的看起&＃xff1a;

第一部分是日志发生的时间
第二部分是日志级别&＃xff0c;这里分别是WARN和INFO
第三部分是输出日志的类&＃xff0c;我们后面也会讲到这个类
第四部分是当前 ES 节点名称
第五部分是 gc 关键词&＃xff0c;我们就从这个关键词聊起。


友情提示&＃xff1a;对 GC 已经了如指掌的同学&＃xff0c;可以直接翻到最后看答案。

2. Elasticsearch 的 GC 组合

Elasticsearch 默认的 GC 配置是CMS GC &＃xff0c;其 Young 区用 ParNew&＃xff0c;Old 区用CMS&＃xff0c;大家可以在 config/jvm.options中看到如下的配置&＃xff1a;

## GC configuration
-XX:&＃43;UseConcMarkSweepGC
-XX:CMSInitiatingOccupancyFraction&＃61;75
-XX:&＃43;UseCMSInitiatingOccupancyOnly


2.3 何时进行回收&＃xff1f;

现在我们已经知道如何找到和回收垃圾了&＃xff0c;那么什么时候回收呢&＃xff1f;简单总结如下&＃xff1a;

1. Young 区的GC 都是在 Eden 区满时触发
2. Serial Old 和 Parallel Old 在 Old 区是在 Young GC 时预测Old 区是否可以为 young 区 promote 到 old 区 的 object 分配空间&＃xff0c;如果不可用则触发 Old GC。这个也可以理解为是 Old区满时。
3. CMS GC 是在 Old 区大小超过一定比例后触发&＃xff0c;而不是 Old 区满。这个原因在于 CMS GC 是并发的算法&＃xff0c;也就是说在 GC 线程收集垃圾的时候&＃xff0c;用户线程也在运行&＃xff0c;因此需要预留一些 Heap 空间给用户线程使用&＃xff0c;防止由于无法分配空间而导致 Full GC 发生。

3. GC Log 如何阅读&＃xff1f;

前面讲了这么多&＃xff0c;终于可以回到开篇的问题了&＃xff0c;我们直接来看答案

[2018-06-30T17:57:23,848][WARN ][o.e.m.j.JvmGcMonitorService] [qoo--eS] [gc][228384] overhead, spent [2.2s] collecting in the last [2.3s]


[gc][这是第228384次GC 检查] 在最近 2.3 s 内花了 2.2s 用来做垃圾收集&＃xff0c;这占比似乎有些过了&＃xff0c;请抓紧来关注下。

[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]}


我们直接来看具体的含义好了&＃xff0c;相信有了前面的 GC 基础知识&＃xff0c;大家在看这里解释的时候就非常清楚了。

1. [gc][本次是 old GC][这是第228385次 GC 检查][从 JVM 启动至今发生的第 160772次 GC]

2. duration [本次检查到的 GC 总耗时 5 秒&＃xff0c;可能是多次的加和],

3. collections [从上次检查至今总共发生1次 GC]/[从上次检查至今已过去 5.1 秒],

4. total [本次检查到的 GC 总耗时为 5 秒]/[从 JVM 启动至今发生的 GC 总耗时为 4.4 天]&＃xff0c;

5. memory [ GC 前 Heap memory 空间]->[GC 后 Heap memory 空间]/[Heap memory 总空间],

6. all_pools(分代部分的详情) {[young 区][GC 前 Memory ]->[GC后 Memory]/[young区 Memory 总大小] } {[survivor 区][GC 前 Memory ]->[GC后 Memory]/[survivor区 Memory 总大小] }{[old 区][GC 前 Memory ]->[GC后 Memory]/[old区 Memory 总大小] }

5. 看看源码

从日志中我们可以看到输出这些日志的类名叫做JvmGcMonitorService&＃xff0c;我们去源码中搜索很快会找到它elasticsearch/core/src/main/java/org/elasticsearch/monitor/jvm/JvmGcMonitorService.java&＃xff0c;这里就不详细展开讲解源码了&＃xff0c;它执行的内容大概如下图所示:

源码请参考&＃xff1a;【ElasticSearch】Es 源码之 MonitorService 源码解读

关于打印日志的格式在源码也有&＃xff0c;如下所示&＃xff1a;

private static final String SLOW_GC_LOG_MESSAGE &＃61;
"[gc][{}][{}][{}] duration [{}], collections [{}]/[{}], total [{}]/[{}], memory [{}]->[{}]/[{}], all_pools {}";
private static final String OVERHEAD_LOG_MESSAGE &＃61; "[gc][{}] overhead, spent [{}] collecting in the last [{}]";


另外细心的同学会发现输出的日志中 gc 只分了 young 和 old &＃xff0c;原因在于 ES 对 GC Name 做了封装&＃xff0c;封装的类为&＃xff1a;org.elasticsearch.monitor.jvm.GCNames&＃xff0c;相关代码如下&＃xff1a;

public static String getByMemoryPoolName(String poolName, String defaultName) {if ("Eden Space".equals(poolName) || "PS Eden Space".equals(poolName) || "Par Eden Space".equals(poolName) || "G1 Eden Space".equals(poolName)) {return YOUNG;}if ("Survivor Space".equals(poolName) || "PS Survivor Space".equals(poolName) || "Par Survivor Space".equals(poolName) || "G1 Survivor Space".equals(poolName)) {return SURVIVOR;}if ("Tenured Gen".equals(poolName) || "PS Old Gen".equals(poolName) || "CMS Old Gen".equals(poolName) || "G1 Old Gen".equals(poolName)) {return OLD;}return defaultName;
}public static String getByGcName(String gcName, String defaultName) {if ("Copy".equals(gcName) || "PS Scavenge".equals(gcName) || "ParNew".equals(gcName) || "G1 Young Generation".equals(gcName)) {return YOUNG;}if ("MarkSweepCompact".equals(gcName) || "PS MarkSweep".equals(gcName) || "ConcurrentMarkSweep".equals(gcName) || "G1 Old Generation".equals(gcName)) {return OLD;}return defaultName;
}


在上面的代码中&＃xff0c;你会看到很多我们在上一节中提到的 GC 算法的名称。

至此&＃xff0c;源码相关部分也讲解完毕&＃xff0c;感兴趣的大家可以自行去查阅。

4. 总结

讲解 GC 的文章已经很多&＃xff0c;本文又唠唠叨叨地讲一遍基础知识&＃xff0c;是希望对于第一次了解 GC 的同学有所帮助。因为只有了解了这些基础知识&＃xff0c;你才不至于被这些 GC 的输出吓懵。希望本文对你理解 ES 的 GC 日志 有所帮助。

5. 参考资料
   Java Hotspot G1 GC的一些关键技术&＃xff08;https://mp.weixin.qq.com/s/4ufdCXCwO56WAJnzng_-ow&＃xff09;
   Understanding Java Garbage Collection&＃xff08;https://www.cubrid.org/blog/understanding-java-garbage-collection&＃xff09;
   《深入理解Java虚拟机&＃xff1a;JVM高级特性与最佳实践》