首页手记你看懂 Elasticsearch Log 中的 GC...

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

标签：

大数据

如果你关注过 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 已经了如指掌的同学，可以直接翻到最后看答案。

1. 什么是 GC？

GC，全称是 Garbage Collection （垃圾收集）或者 Garbage Collector(垃圾收集器)。

在使用 C语言编程的时候，我们要手动的通过 malloc 和 free来申请和释放数据需要的内存，如果忘记释放内存，就会发生内存泄露的情况，即无用的数据占用了宝贵的内存资源。而Java 语言编程不需要显示的申请和释放内存，因为 JVM 可以自动管理内存，这其中最重要的一部分就是 GC，即 JVM 可以自主地去释放无用数据（垃圾）占用的内存。

我们研究 GC 的主要原因是 GC 的过程会有 Stop The World(STW)的情况发生，即此时用户线程会停止工作，如果 STW 的时间过长，则应用的可用性、实时性等就下降的很厉害。

GC主要解决如下3个问题：

如何找到垃圾？
如何回收垃圾？
何时回收垃圾？

我们一个个来看下。

1.1 如何找到垃圾？

所谓垃圾，指的是不再被使用（引用）的对象。Java 的对象都是在堆(Heap)上创建的，我们这里默认也只讨论堆。那么现在问题就变为如何判定一个对象是否还有被引用，思路主要有如下两种：

引用计数法，即在对象被引用时加1，去除引用时减1，如果引用值为0，即表明该对象可回收了。
可达性分析法，即通过遍历已知的存活对象(GC Roots)的引用链来标记出所有存活对象

方法1简单粗暴效率高，但准确度不行，尤其是面对互相引用的垃圾对象时无能为力。

方法2是目前常用的方法，这里有一个关键是 GC Roots，它是判定的源头，感兴趣的同学可以自己去研究下，这里就不展开讲了。

1.2 如何回收垃圾？

垃圾找到了，该怎么回收呢？看起来似乎是个很傻的问题。直接收起来扔掉不就好了？！对应到程序的操作，就是直接将这些对象占用的空间标记为空闲不就好了吗？那我们就来看一下这个基础的回收算法：标记-清除(Mark-Sweep)算法。

1.2.1 标记-清除算法(Mark Sweep)

该算法很简单，使用通过可达性分析分析方法标记出垃圾，然后直接回收掉垃圾区域。它的一个显著问题是一段时间后，内存会出现大量碎片，导致虽然碎片总和很大，但无法满足一个大对象的内存申请，从而导致 OOM，而过多的内存碎片（需要类似链表的数据结构维护），也会导致标记和清除的操作成本高，效率低下，如下图所示：

1.2.2 复制算法(Copying)

为了解决上面算法的效率问题，有人提出了复制算法。它将可用内存一分为二，每次只用一块，当这一块内存不够用时，便触发 GC，将当前存活对象复制(Copy)到另一块上，以此往复。这种算法高效的原因在于分配内存时只需要将指针后移，不需要维护链表等。但它最大的问题是对内存的浪费，使用率只有 50%。

但这种算法在一种情况下会很高效：Java 对象的存活时间极短。据 IBM 研究，Java 对象高达 98% 是朝生夕死的，这也意味着每次 GC 可以回收大部分的内存，需要复制的数据量也很小，这样它的执行效率就会很高。

1.2.3 标记-整理算法(Mark Compact)

该算法解决了第1中算法的内存碎片问题，它会在回收阶段将所有内存做整理，如下图所示：

但它的问题也在于增加了整理阶段，也就增加了 GC 的时间。

1.2.4 分代收集算法(Generation Collection)

既然大部分 Java 对象是朝生夕死的，那么我们将内存按照 Java 生存时间分为 新生代(Young) 和 老年代(Old)，前者存放短命僧，后者存放长寿佛，当然长寿佛也是由短命僧升级上来的。然后针对两者可以采用不同的回收算法，比如对于新生代采用复制算法会比较高效，而对老年代可以采用标记-清除或者标记-整理算法。这种算法也是最常用的。JVM Heap 分代后的划分一般如下所示，新生代一般会分为 Eden、Survivor0、Survivor1区，便于使用复制算法。

将内存分代后的 GC 过程一般类似下图所示：

对象一般都是先在 Eden区创建
当Eden区满，触发 Young GC，此时将 Eden中还存活的对象复制到 S0中，并清空 Eden区后继续为新的对象分配内存
当Eden区再次满后，触发又一次的 Young GC，此时会将 Eden和S0中存活的对象复制到 S1中，然后清空Eden和S0后继续为新的对象分配内存
每经过一次 Young GC，存活下来的对象都会将自己存活次数加1，当达到一定次数后，会随着一次 Young GC 晋升到 Old区
Old区也会在合适的时机进行自己的 GC

1.2.5 常见的垃圾收集器

前面我们讲了众多的垃圾收集算法，那么其具体的实现就是垃圾收集器，也是我们实际使用中会具体用到的。现代的垃圾收集机制基本都是分代收集算法，而 Young与 Old区分别有不同的垃圾收集器，简单总结如下图：

从上图我们可以看到 Young与 Old区有不同的垃圾收集器，实际使用时会搭配使用，也就是上图中两两连线的收集器是可以搭配使用的。这些垃圾收集器按照运行原理大概可以分为如下几类：

Serial GC，串行，单线程的收集器，运行 GC 时需要停止所有的用户线程，且只有一个 GC 线程
Parallel GC，并行，多线程的收集器，是 Serial 的多线程版，运行时也需要停止所有用户线程，但同时运行多个 GC 线程，所以效率高一些
Concurrent GC，并发，多线程收集器，GC 分多阶段执行，部分阶段允许用户线程与 GC 线程同时运行，这也就是并发的意思，大家要和并行做一个区分。
其他

我们下面简单看一下他们的运行机制。

1.2.5.1 Serial GC

该类 Young区的为 Serial GC，Old区的为Serial Old GC。执行大致如下所示：

1.2.5.2 Parallel GC

该类Young 区的有 ParNew和 Parallel Scavenge，Old 区的有Parallel Old。其运行机制如下，相比 Serial GC ，其最大特点在于 GC 线程是并行的，效率高很多：

1.2.5.3 Concurrent Mark-Sweep GC

该类目前只是针对 Old 区，最常见就是CMS GC，它的执行分为多个阶段，只有部分阶段需要停止用户进程，这里不详细介绍了，感兴趣可以去找相关文章来看，大体执行如下：

1.2.5.4 其他

目前最新的 GC 有G1GC和ZGC，其运行机制与上述均不相同，虽然他们也是分代收集算法，但会把 Heap 分成多个 region 来做处理，这里不展开讲，感兴趣的可以参看最后参考资料的内容。

1.2.6 Elasticsearch 的 GC 组合

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


## GC configuration

-XX:+UseConcMarkSweepGC

-XX:CMSInitiatingOccupancyFraction=75

-XX:+UseCMSInitiatingOccupancyOnly

1.3 何时进行回收？

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

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

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

[gc][本次是 old GC][这是第228385次 GC 检查][从 JVM 启动至今发生的第 160772次 GC]
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]/[survivor区 Memory 总大小] }{[old 区][GC 前 Memory ]->[GC后 Memory]/[old区 Memory 总大小] }

3. 看看源码

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

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


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;

    }