GC日志解析

GC日志

Java应用程序的GC日志对分析定位很多性能问题有着非常大的帮助。默认情况下，Java应用程序不会自动产生GC日志。如果需要输出GC日志，必须在JVM启动时增加对应的参数。

-XX:+PrintGC 输出GC日志

-XX:+PrintGCDetails 输出GC的详细日志

-XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)

-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式，如 2013-05-04T21:53:59.234+0800)

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息

-Xloggc:../logs/gc.log 日志文件的输出路径

kubernetes 容器环境JVM内存配置最佳实践，参考 kubernetes

JVM信息


OpenJDK 64-Bit Server VM (25.332-b09) for linux-amd64 JRE (1.8.0_332-BiSheng_JDK_Enterprise_2.1.0.330.B003-b09), built on May 13 2022 20:00:00 by "huawei" with gcc 7.3.0
Memory: 4k page, physical 63486004k(2502736k free), swap 0k(0k free)
CommandLine flags: -XX:CICompilerCount=12 -XX:CMSInitiatingOccupancyFraction=80 -XX:+CMSParallelRemarkEnabled -XX:CompressedClassSpaceSize=528482304 -XX:ErrorFile=/var/log/Bigdata/hbase/rs/hs_err_pid_%p.log -XX:GCLogFileSize=1048576 -XX:InitialHeapSize=33285996544 -XX:MaxHeapSize=33285996544 -XX:MaxMetaspaceSize=536870912 -XX:MaxNewSize=4294967296 -XX:MaxTenuringThreshold=6 -XX:MetaspaceSize=134217728 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=4294967296 -XX:NumberOfGCLogFiles=10 -XX:OldPLABSize=16 -XX:OldSize=28991029248 -XX:-OmitStackTraceInFastThrow -XX:OnOutOfMemoryError=kill -9 %p -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseFastUnorderedTimeStamps -XX:+UseGCLogFileRotation -XX:+UseParNewGC

这些日志提供了关于你的Java虚拟机 (JVM) 和运行时环境的一些重要信息。让我解释一下：

OpenJDK 64-Bit Server VM (25.332-b09) for linux-amd64 JRE (1.8.0_332-BiSheng_JDK_Enterprise_2.1.0.330.B003-b09): 这是你所使用的Java虚拟机 (JVM) 和运行时环境的版本信息。
Memory: 4k page, physical 63486004k(2502736k free), swap 0k(0k free): 这部分提供了物理内存和交换空间的信息，包括页面大小、总物理内存、可用物理内存、总交换空间和可用交换空间。
CommandLine flags: 这里列出了JVM启动时使用的命令行标志，包括一些与内存管理相关的标志，例如初始堆大小、最大堆大小、新生代大小、永久代大小等。还有一些与垃圾收集器相关的标志，如使用的垃圾收集器类型等。

根据这些信息，正在使用OpenJDK 64位服务器虚拟机，在Linux上运行版本为1.8.0_332的JRE。你的JVM配置中包含了一些与内存管理和垃圾收集器相关的参数。

串行Serial GC

参数: -XX:+UseSerialGC

并行Parallel GC

参数: -XX:+UseParallelGC

DefNew：是使用-XX:+UseSerialGC（新生代，老年代都使用串行回收收集器）。

ParNew：是使用-XX:+UseParNewGC（新生代使用并行收集器，老年代使用串行回收收集器）或者-XX:+UseConcMarkSweepGC(新生代使用并行收集器，老年代使用CMS)。

PSYoungGen：是使用-XX:+UseParallelOldGC（新生代，老年代都使用并行回收收集器）或者-XX:+UseParallelGC（新生代使用并行回收收集器，老年代使用串行收集器）

garbage-first heap：是使用-XX:+UseG1GC（G1收集器）

参考: ParNew 和 PSYoungGen 和 DefNew 是一个东西么

日志解析


x
    4 2024-05-09T18:43:34.546+0800: 4.424: [GC (Allocation Failure) 2024-05-09T18:43:34.546+0800: 4.424: [DefNew: 419456K->11392K(471872K), 0.0847101 secs] 419456K->11392K(1520448K), 0.0847802 secs] [Times: user=0.04 sys=0.01, real=0.09 secs]

    8 2024-05-09T18:50:46.739+0800: 436.616: [Full GC (Metadata GC Threshold) 2024-05-09T18:50:46.739+0800: 436.616: [Tenured: 0K->30786K(1048576K), 0.1947356 secs] 269275K->30786K(1520448K), [Metaspace: 61986K->61986K(1105920K)], 0.1948064 secs] [Times: user=0.14 sys=0.02, real=0.20 secs]

DefNew 表示使用的是年轻代的垃圾收集器（可能是串行收集器或并行收集器）。
Tenured 表示老年代的垃圾收集器，处理老年代的垃圾收集。可能是串行收集器（Serial GC）或者并行收集器（Parallel GC）。

第一次 GC (Allocation Failure)

时间戳: 2024-05-09T18:43:34.546+0800
触发时间: 4.424，JVM启动后到触发GC的时间，单位为秒。
GC类型: [GC (Allocation Failure)]，这是由于新生代内存分配失败而触发的GC。
新生代变化: DefNew: 419456K->11392K(471872K), 0.0847101 secs，新生代（Eden区和两个Survivor区）的变化：
- GC之前新生代使用的内存：419456K，GC之后新生代使用的内存：11392K，新生代总容量：471872K（约460MB），GC耗时：0.0847101秒。
堆内存变化: 419456K->11392K(1520448K)，整个堆内存的变化：
- GC之前堆内存使用量：419456K，GC之后堆内存使用量：11392K，堆内存总容量：1520448K（1.5GB）
时间详细信息: [Times: user=0.04 sys=0.01, real=0.09 secs]，用户时间（CPU时间）：0.04秒，系统时间：0.01秒，实际时间：0.09秒

第二次 Full GC (Metadata GC Threshold)

时间戳: 2024-05-09T18:50:46.739+0800
触发时间: 436.616，JVM启动后到触发GC的时间，单位为秒。
GC类型: [Full GC (Metadata GC Threshold)]，这是由于达到元数据GC阈值而触发的Full GC。
老年代变化: Tenured: 0K->30786K(1048576K), 0.1947356 secs，老年代（旧生代）GC前后的情况：
- GC之前使用的内存：0K，GC之后使用的内存：30786K，老年代总容量：1048576K（1GB），GC操作耗时：0.1947356秒。
Metaspace变化: [Metaspace: 61986K->61986K(1105920K)]，Metaspace（类元数据）在GC前后的情况：
- GC之前Metaspace使用的内存：61986K，GC之后Metaspace使用的内存：61986K，Metaspace总容量：1105920K（1.1GB）
堆内存变化: 269275K->30786K(1520448K)，描述了整个堆内存的变化：
- GC之前堆内存使用量：269275K，GC之后堆内存使用量：30786K，堆内存总容量：1520448K（1.5GB）
时间详细信息: [Times: user=0.14 sys=0.02, real=0.20 secs]

CMS GC日志

CMS（Concurrent Mark Sweep，并发-标记-清除）是目前最常用的 JVM 垃圾回收器，这里不解释 CMS 的工作过程，只记录一些基础要点以帮助理解后面的内容：

CMS 是一种基于并发、使用标记清除算法的垃圾回收器。CMS 会尽可能让 GC 线程与用户线程并发执行，可以消除长时间的 GC 停顿（STW）。
CMS 不会对新生代做垃圾回收，默认只针对老年代进行垃圾回收。此外，CMS 还可以开启对永久代的垃圾回收（或元空间），避免由于 PermGen 空间耗尽带来 Full GC，JDK6以上受参数 -XX:+CMSClassUnloadingEnabled 控制，这个参数在 JDK8 之前默认关闭，JDK8 默认开启了。
CMS 要与一个新生代垃圾回收器搭配使用，所谓"分代收集"。能与 CMS 配合工作的新生代回收器有 Serial 收集器和 ParNew 收集器，我们一般使用支持多线程执行的 ParNew 收集器。
使用 CMS GC 策略时，GC 类别可以分为：Young GC（又称 Minor GC），Old GC（又称 Major GC、CMS GC），以及Full GC。其中 Full GC 是对整个堆的垃圾回收，STW 时间较长，对业务影响较大，应该尽量避免 Full GC。

GC 的设计目标是避免在老年代垃圾收集时出现长时间的卡顿

参数: -XX:+UseParNewGC, -XX:+UseConcMarkSweepGC


xxxxxxxxxx
2024-06-03T15:42:34.511+0800: 1639863.519: [GC (Allocation Failure) 2024-06-03T15:42:34.511+0800: 1639863.519: [ParNew: 3774912K->419390K(3774912K), 1.6847681 secs] 22823411K->21044544K(32086464K), 1.6850241 secs] [Times: user=18.60 sys=0.00, real=1.69 secs] 
2024-06-03T15:42:44.095+0800: 1639873.104: [GC (Allocation Failure) 2024-06-03T15:42:44.095+0800: 1639873.104: [ParNew: 3774910K->419392K(3774912K), 1.8020686 secs] 24400064K->22711372K(32086464K), 1.8023782 secs] [Times: user=19.62 sys=0.00, real=1.80 secs] 
2024-06-03T15:44:33.904+0800: 1639982.913: [GC (Allocation Failure) 2024-06-03T15:44:33.904+0800: 1639982.913: [ParNew: 3774912K->419392K(3774912K), 0.4937775 secs] 26066892K->23189504K(32086464K), 0.4940421 secs] [Times: user=4.90 sys=0.00, real=0.49 secs] 


2024-06-03T15:44:34.402+0800: 1639983.410: [GC (CMS Initial Mark) [1 CMS-initial-mark: 22770112K(28311552K)] 23190516K(32086464K), 0.0738273 secs] [Times: user=0.80 sys=0.00, real=0.07 secs] 
2024-06-03T15:44:34.476+0800: 1639983.485: [CMS-concurrent-mark-start]
2024-06-03T15:44:37.587+0800: 1639986.595: [CMS-concurrent-mark: 3.105/3.111 secs] [Times: user=12.87 sys=0.25, real=3.11 secs] 
2024-06-03T15:44:37.587+0800: 1639986.595: [CMS-concurrent-preclean-start]
2024-06-03T15:44:37.715+0800: 1639986.724: [CMS-concurrent-preclean: 0.123/0.128 secs] [Times: user=0.13 sys=0.00, real=0.13 secs] 
2024-06-03T15:44:37.715+0800: 1639986.724: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2024-06-03T15:44:42.760+0800: 1639991.769: [CMS-concurrent-abortable-preclean: 5.038/5.045 secs] [Times: user=5.52 sys=0.00, real=5.04 secs] 
2024-06-03T15:44:42.764+0800: 1639991.773: [GC (CMS Final Remark) [YG occupancy: 779103 K (3774912 K)]2024-06-03T15:44:42.764+0800: 1639991.773: [Rescan (parallel) , 0.1013049 secs]2024-06-03T15:44:42.865+0800: 1639991.874: [weak refs processing, 0.0004149 secs]2024-06-03T15:44:42.866+0800: 1639991.874: [class unloading, 0.0827228 secs]2024-06-03T15:44:42.948+0800: 1639991.957: [scrub symbol table, 0.0108268 secs]2024-06-03T15:44:42.959+0800: 1639991.968: [scrub string table, 0.0010165 secs][1 CMS-remark: 22770112K(28311552K)] 23549215K(32086464K), 0.1965759 secs] [Times: user=1.14 sys=0.00, real=0.19 secs] 
2024-06-03T15:44:42.961+0800: 1639991.970: [CMS-concurrent-sweep-start]
2024-06-03T15:44:51.949+0800: 1640000.958: [CMS-concurrent-sweep: 8.978/8.988 secs] [Times: user=9.15 sys=0.37, real=8.99 secs] 
2024-06-03T15:44:51.949+0800: 1640000.958: [CMS-concurrent-reset-start]
2024-06-03T15:44:51.988+0800: 1640000.996: [CMS-concurrent-reset: 0.035/0.038 secs] [Times: user=0.04 sys=0.00, real=0.04 secs] 

// 一共6个步骤，四个步骤是并发执行,CMS 使用的并发线程数等于CPU 核心数的1/4
[GC (CMS Initial Mark) [1 CMS-initial-mark: 207528K(349568K)] 225479K(506816K), 0.0009352 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Initial Mark(初始标记)：当前步骤需要JVM暂停STW，标记的根对象GC root
[CMS-concurrent-mark-start] Concurrent Mark(并发标记)
[CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Concurrent Preclean(并发预清理)
[CMS-concurrent-preclean-start] Final Remark(最终标记) 这个阶段的停顿时间一般会比初始标记阶段的时间稍长
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Concurrent Sweep(并发清除)
[CMS-concurrent-abortable-preclean-start] Concurrent Reset(并发重置)


2024-06-03T15:46:05.320+0800: 1640074.329: [GC (Allocation Failure) 2024-06-03T15:46:05.320+0800: 1640074.329: [ParNew: 3774912K->408582K(3774912K), 0.2985388 secs] 18648716K->15666335K(32086464K), 0.2988320 secs] [Times: user=2.95 sys=0.19, real=0.30 secs] 
2024-06-03T15:46:55.633+0800: 1640124.641: [GC (Allocation Failure) 2024-06-03T15:46:55.633+0800: 1640124.642: [ParNew: 3764102K->106083K(3774912K), 0.0280070 secs] 19021855K->15363836K(32086464K), 0.0282948 secs] [Times: user=0.32 sys=0.02, real=0.02 secs] 
2024-06-03T15:47:18.413+0800: 1640147.421: [GC (Allocation Failure) 2024-06-03T15:47:18.413+0800: 1640147.422: [ParNew: 3461603K->419392K(3774912K), 1.3323800 secs] 18719356K->16642625K(32086464K), 1.3327232 secs] [Times: user=14.94 sys=0.01, real=1.33 secs]

这些日志条目看起来是Java虚拟机 (JVM) 的垃圾收集器 (Garbage Collector) 的输出。让我解释一下：

GC (Allocation Failure): 垃圾收集器在处理内存分配失败时进行了垃圾回收。
1. ParNew: 这是新生代垃圾收集器的名称，它负责收集新分配的对象。在这里，新生代从 3774912K 减少到 419392K，总内存大小为 3774912K，并且此操作耗时 0.4937775 秒。
2. 26066892K->23189504K(32086464K): 整个堆内存从 26,066,892K 减少到 23,189,504K，总内存大小为 32,086,464K。
GC (CMS Initial Mark): CMS是"Concurrent Mark-Sweep"的缩写，是一种并发标记清除垃圾收集器。在这里，CMS执行了初始标记阶段，耗时 0.0738273 秒。当前步骤需要JVM暂停STW，标记的根对象GC root。
CMS-concurrent-mark-start: CMS开始并发标记阶段。
CMS-concurrent-mark: 并发标记阶段耗时 3.11 秒，其中用户时间为 12.87 秒。
CMS-concurrent-preclean-start: CMS开始并发预清理阶段。
CMS-concurrent-preclean: 并发预清理阶段耗时 0.13 秒。
CMS-concurrent-abortable-preclean-start: CMS开始可中止的并发预清理阶段。
CMS: abort preclean due to time: 由于时间原因，CMS中止了预清理阶段。
GC (CMS Final Remark): CMS执行最终的备注阶段。这个阶段包括重新扫描、弱引用处理、类卸载、符号表清理和字符串表清理。
CMS-concurrent-sweep-start: CMS开始并发清理阶段。
CMS-concurrent-sweep: 并发清理阶段耗时 8.99 秒。
CMS-concurrent-reset-start: CMS开始并发重置阶段。
CMS-concurrent-reset: 并发重置阶段耗时 0.04 秒。

这些日志提供了垃圾收集器在执行过程中的详细信息，包括各个阶段的耗时以及内存的变化情况。

G1 GC日志

添加参数: -XX:+UseG1GC

通过划分多个内存区域做增量整理和回收，进一步降低延迟 G1 的全称是Garbage-First，意为垃圾优先，哪一块的垃圾最多就优先清理它 G1 GC 最主要的设计目标是：将STW 停顿的时间和分布，变成可预期且可配置的堆不再分成年轻代和老年代，而是划分为多个（通常是2048 个）可以存放对象的小块堆区域(smaller heap regions)。每个小块，可能一会被定义成Eden 区，一会被指定为Survivor区或者Old 区。在逻辑上，所有的Eden 区和Survivor区合起来就是年轻代，所有的Old 区拼在一起那就是老年 Java8默认并行Parallel GC，Java9， Java11 默认G1GC


xxxxxxxxxx
2021-02-24T07:28:03.140+0800: [GC pause (G1 Evacuation Pause) (young) 32M->11M(512M), 0.0028508 secs]
2021-02-24T07:28:03.153+0800: [GC pause (G1 Evacuation Pause) (young) 39M->20M(512M), 0.0027907 secs]
2021-02-24T07:28:03.178+0800: [GC pause (G1 Evacuation Pause) (young) 67M->37M(512M), 0.0042861 secs]
2021-02-24T07:28:03.208+0800: [GC pause (G1 Evacuation Pause) (young) 102M->60M(512M), 0.0052239 secs]
2021-02-24T07:28:03.276+0800: [GC pause (G1 Evacuation Pause) (young) 214M->108M(512M), 0.0072020 secs]
2021-02-24T07:28:03.316+0800: [GC pause (G1 Evacuation Pause) (young) 242M->149M(512M), 0.0077214 secs]


2021-02-24T07:28:03.383+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 342M->202M(512M), 0.0342600 secs]
2021-02-24T07:28:03.417+0800: [GC concurrent-root-region-scan-start]
2021-02-24T07:28:03.419+0800: [GC concurrent-root-region-scan-end, 0.0012973 secs]
2021-02-24T07:28:03.419+0800: [GC concurrent-mark-start]
2021-02-24T07:28:03.422+0800: [GC concurrent-mark-end, 0.0024423 secs]
2021-02-24T07:28:03.422+0800: [GC remark, 0.0017725 secs]
2021-02-24T07:28:03.424+0800: [GC cleanup 228M->228M(512M), 0.0012586 secs]

阶段1: Initial Mark(初始标记)
阶段2: Root Region Scan(Root区扫描)
阶段3: Evacuation Pause (mixed)(转移暂停: 混合模式)
阶段4: Remark(再次标记)
阶段5: Cleanup(清理)


2021-02-24T07:28:03.471+0800: [GC pause (G1 Evacuation Pause) (young)-- 406M->307M(512M), 0.0083992 secs]
2021-02-24T07:28:03.480+0800: [GC pause (G1 Evacuation Pause) (mixed) 310M->299M(512M), 0.0048689 secs]

这些日志看起来是来自Java虚拟机 (JVM) 的垃圾收集器的输出。让我来解释一下各个部分的含义：

[GC pause (G1 Evacuation Pause) (young) 242M->149M(512M), 0.0077214 secs]: 这条日志指示了一次年轻代（young generation）的垃圾收集暂停事件。在这个事件中，从242兆字节减少到149兆字节，堆大小为512兆字节，整个垃圾收集过程持续了0.0077214秒。
[GC pause (G1 Humongous Allocation) (young) (initial-mark) 342M->202M(512M), 0.0342600 secs]: 这条日志说明了一次巨型对象分配（humongous allocation）导致的年轻代垃圾收集事件，同时也包含了初始标记阶段（initial-mark）。在此事件中，堆内存从342兆字节减少到202兆字节，总共持续了0.0342600秒。
[GC concurrent-root-region-scan-start] 和 [GC concurrent-root-region-scan-end, 0.0012973 secs]: 这部分表示并发阶段的根区域扫描开始和结束。
[GC concurrent-mark-start] 和 [GC concurrent-mark-end, 0.0024423 secs]: 这部分表示并发标记阶段的开始和结束。
[GC remark, 0.0017725 secs]: 这条日志表示重新标记阶段的持续时间。
[GC cleanup 228M->228M(512M), 0.0012586 secs]: 这部分指示了清理阶段的持续时间，以及在清理后堆的使用情况。
[GC pause (G1 Evacuation Pause) (young)-- 406M->307M(512M), 0.0083992 secs]: 这是另一次年轻代垃圾收集暂停事件，其中包括了两个减号（--），表示这是一次特殊情况下的垃圾收集暂停。
[GC pause (G1 Evacuation Pause) (mixed) 310M->299M(512M), 0.0048689 secs]: 这是一次混合垃圾收集暂停事件，其中包含了年轻代和老年代的对象。

这些日志提供了有关垃圾收集过程中不同阶段的信息，包括暂停事件、并发阶段和各阶段的持续时间。通过这些日志，你可以了解JVM在运行时是如何进行垃圾收集的。如果你需要更多关于这些日志的解释或者有其他相关问题，欢迎随时提问。