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

1.概述

转载：https://elasticsearch.cn/article/812

如果你关注过 elasticsearch 的日志，可能会看到如下类似的内容：

[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 相关的日志，那么你了解每一部分的含义吗？如果不了解，你可以继续往下看了。

我们先从最简单的看起：

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

友情提示：对 GC 已经了如指掌的同学，可以直接翻到最后看答案。

2. Elasticsearch 的 GC 组合

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

## GC configuration
-XX:+UseConcMarkSweepGC
-XX:CMSInitiatingOccupancyFraction=75
-XX:+UseCMSInitiatingOccupancyOnly

2.3 何时进行回收？

现在我们已经知道如何找到和回收垃圾了，那么什么时候回收呢？简单总结如下：

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

3. GC Log 如何阅读？

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

[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 用来做垃圾收集，这占比似乎有些过了，请抓紧来关注下。

[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 基础知识，大家在看这里解释的时候就非常清楚了。

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

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

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

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

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，我们去源码中搜索很快会找到它elasticsearch/core/src/main/java/org/elasticsearch/monitor/jvm/JvmGcMonitorService.java，这里就不详细展开讲解源码了，它执行的内容大概如下图所示:

源码请参考：【ElasticSearch】Es 源码之 MonitorService 源码解读

关于打印日志的格式在源码也有，如下所示：

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

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

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;
}

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

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

4. 总结

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

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