GC日志详解

对于 java 应用我们可以通过一些配置把程序运行过程中的 gc 日志全部打印出来，然后分析 gc 日志得到关键性指标，分析 GC 原因，调优 JVM 参数：

开启 GC 日志相关参数

java -jar 
‐Xloggc:./gc‐%t.log 
‐XX:+PrintGCDetails 
‐XX:+PrintGCDateStamps 
‐XX:+PrintGCTimeStamps 
‐XX:+PrintGCCause   
‐XX:+UseGCLogFileRotation 
‐XX:NumberOfGCLogFiles=10 
‐XX:GCLogFileSize=100M
main.jar
  • gc-%t.log 日志文件带时间
  • +PrintGCDetails 打印详细信息
  • +PrintGCDateStamps 打印日期
  • +PrintGCTimeStamps 打印时间
  • +PrintGCCause 打印 GC 原因
  • +UseGCLogFileRotation 开启日志轮换
  • NumberOfGCLogFiles GC 日志保留个数
  • GCLogFileSize 每个日志文件的大小

查看jvm所有参数

  • java -XX:+PrintFlagsInitial 表示打印出所有参数选项的默认值
  • java -XX:+PrintFlagsFinal 表示打印出所有参数选项在运行程序时生效的值

GC 日志分析

我们可以看到图中第一行红框，是项目的配置参数。这里不仅配置了打印 GC 日志，还有相关的 VM 内存参数。
第二行红框中的是在这个 GC 时间点发生 GC 之后相关 GC 情况。

  1. 对于 2.909： 这是从 jvm 启动开始计算到这次 GC 经过的时间，前面还有具体的发生时间日期。
  2. Full GC(Metadata GC Threshold)指这是一次 full gc，括号里是 gc 的原因， PSYoungGen 是年轻代的 GC， ParOldGen 是老年代的 GC，Metaspace 是元空间的 GC
  3. 6160K->0K(141824K)，这三个数字分别对应 GC 之前占用年轻代的大小，GC 之后年轻代占用，以及整个年轻代的大小。
  4. 112K->6056K(95744K)，这三个数字分别对应 GC 之前占用老年代的大小，GC 之后老年代占用，以及整个老年代的大小。
  5. 6272K->6056K(237568K)，这三个数字分别对应 GC 之前占用堆内存的大小，GC 之后堆内存占用，以及整个堆内存的大小。
  6. 20516K->20516K(1069056K)，这三个数字分别对应 GC 之前占用元空间内存的大小，GC 之后元空间内存占用，以及整个元空间内存的大小。
  7. 0.0209707 是该时间点 GC 总耗费时间

从日志可以发现几次fullgc都是由于元空间不够导致的，所以我们可以将元空间调大点：

‐XX:MetaspaceSize=256M ‐XX:MaxMetaspaceSize=256M

GC日日志分析工具

GC 日志太多，人工无法很好的分析出原因，可以利用一些工具：

  • gceasy https://gceasy.io/
    以图形的方式展现内存变化等，还会给出一些 jvm 参数优化的建议，目前这个功能应该收费了

GC日志对性能的影响

其实GC日志就是 jvm 执行期间那些 C++ 代码打印的日志而已，和我们应用中的日志没有差别，只要系统没有非常频繁的发生GC 会导致日志太大，对应用造成的性能影响可以忽略