读懂parallel gc log

一、Java8 ,HotspotVM, 核心参数：

CommandLine flags:

-XX:+AlwaysPreTouch
-XX:CompressedClassSpaceSize=528482304
-XX:ErrorFile=/app/logs/my-biz/hs_err_%p.log
-XX:GCLogFileSize=1048576000
-XX:+HeapDumpBeforeFullGC 【因为是测试环境，所以加了这个参数】
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/app/logs/my-biz
-XX:InitialHeapSize=17179869184
-XX:MaxHeapSize=17179869184
-XX:MaxMetaspaceSize=536870912
-XX:MetaspaceSize=268435456
-XX:NewRatio=1
-XX:NumberOfGCLogFiles=5
-XX:-OmitStackTraceInFastThrow
-XX:+PrintCommandLineFlags
-XX:+PrintFlagsFinal
-XX:+PrintGC
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-XX:+UnlockDiagnosticVMOptions
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:+UseGCLogFileRotation
-XX:+UseParallelGC  【注意这里用的java8默认的parallelgc，不是cms+parNew】
-XX:-UseAdaptiveSizePolicy 【这个参数没加】

1.1 AlwaysPreTouch

-XX:+AlwaysPreTouch 是 Java 虚拟机参数之一，它指示 JVM 在启动时预先分配和锁定（Touch）Java 堆内存的所有页面。预先分配和锁定内存页面可以帮助确保 JVM 在运行时不会因为内存分配延迟导致停顿或性能下降。

具体来说，-XX:+AlwaysPreTouch 的作用包括：

提前分配内存：JVM 在启动时会分配整个 Java 堆内存的空间，并将其全部锁定。这意味着在应用程序运行期间不会发生内存分配（除非 Java 堆被动态扩展）。

避免内存分配延迟：在 Java 应用程序运行期间，如果需要更多的内存，通常需要动态分配。但如果系统内存不足，动态分配内存可能会导致操作系统进行虚拟内存的分页操作，这可能会引起较大的性能开销。通过预先分配和锁定内存，可以避免这种情况。

降低垃圾回收延迟：在某些情况下，内存分配操作可能会导致垃圾回收（GC）的停顿时间增加。通过预先分配内存，可以降低垃圾回收操作对系统性能的影响。

二、 gc log

应用在跑了一段时间后，gc log如下，这里主要是记录下备忘：

2024-02-20T17:30:45.436+0800: 21056.921: Total time for which application threads were stopped: 0.0039479 seconds, Stopping threads took: 0.0004651 seconds

#第1097 次 gc （GCLocker Initiated GC，不过为啥也会引发垃圾回收呢？TODO）；此时还没有fullgc 
{Heap before GC invocations=1097 (full 0):
 PSYoungGen      total 6738432K, used 6732547K [0x00000005e0800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 6044672K, 99% used [0x00000005e0800000,0x0000000751142610,0x0000000751700000)
  from space 693760K, 99% used [0x00000007b6280000,0x00000007e07fe630,0x00000007e0800000)
  to   space 1171968K, 0% used [0x0000000751700000,0x0000000751700000,0x0000000798f80000)
 ParOldGen       total 8388608K, used 4992341K [0x00000003e0800000, 0x00000005e0800000, 0x00000005e0800000)
  object space 8388608K, 59% used [0x00000003e0800000,0x00000005113556b0,0x00000005e0800000)
 Metaspace       used 139136K, capacity 151259K, committed 151424K, reserved 1183744K
  class space    used 15678K, capacity 17502K, committed 17536K, reserved 1048576K
2024-02-20T17:30:45.459+0800: 21056.945: [GC (GCLocker Initiated GC) [PSYoungGen: 6732547K->1171955K(7216640K)] 11724888K->7372510K(15605248K), 0.2131267 secs] [Times: user=6.32 sys=1.22, real=0.22 secs] 
Heap after GC invocations=1097 (full 0):
 PSYoungGen      total 7216640K, used 1171955K [0x00000005e0800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 6044672K, 0% used [0x00000005e0800000,0x00000005e0800000,0x0000000751700000)
  from space 1171968K, 99% used [0x0000000751700000,0x0000000798f7cf40,0x0000000798f80000)
  to   space 1171968K, 0% used [0x0000000798f80000,0x0000000798f80000,0x00000007e0800000)
 ParOldGen       total 8388608K, used 6200554K [0x00000003e0800000, 0x00000005e0800000, 0x00000005e0800000)
  object space 8388608K, 73% used [0x00000003e0800000,0x000000055af3a950,0x00000005e0800000)
 Metaspace       used 139136K, capacity 151259K, committed 151424K, reserved 1183744K
  class space    used 15678K, capacity 17502K, committed 17536K, reserved 1048576K
}


2024-02-20T17:30:45.673+0800: 21057.158: Total time for which application threads were stopped: 0.2279374 seconds, Stopping threads took: 0.0038452 seconds
2024-02-20T17:30:46.057+0800: 21057.542: Total time for which application threads were stopped: 0.0123185 seconds, Stopping threads took: 0.0025314 seconds
# 第1098次 gc （GC (Allocation Failure），此时也没有full gc 。【注意】新生代的大小发生了 变化！！！因为我们没有加【-XX:-UseAdaptiveSizePolicy】
{Heap before GC invocations=1098 (full 0):
 PSYoungGen      total 7216640K, used 7216627K [0x00000005e0800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 6044672K, 100% used [0x00000005e0800000,0x0000000751700000,0x0000000751700000)
  from space 1171968K, 99% used [0x0000000751700000,0x0000000798f7cf40,0x0000000798f80000)
  to   space 1171968K, 0% used [0x0000000798f80000,0x0000000798f80000,0x00000007e0800000)
 ParOldGen       total 8388608K, used 6440555K [0x00000003e0800000, 0x00000005e0800000, 0x00000005e0800000)
  object space 8388608K, 76% used [0x00000003e0800000,0x000000056999afd8,0x00000005e0800000)
 Metaspace       used 139141K, capacity 151323K, committed 151424K, reserved 1183744K
  class space    used 15678K, capacity 17502K, committed 17536K, reserved 1048576K
2024-02-20T17:30:46.712+0800: 21058.197: [GC (Allocation Failure) [PSYoungGen: 7216627K->1171953K(4494848K)] 13657183K->9195030K(12883456K), 0.1764428 secs] [Times: user=3.97 sys=2.57, real=0.17 secs] 
Heap after GC invocations=1098 (full 0):
 PSYoungGen      total 4494848K, used 1171953K [0x00000005e0800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 3322880K, 0% used [0x00000005e0800000,0x00000005e0800000,0x00000006ab500000)
  from space 1171968K, 99% used [0x0000000798f80000,0x00000007e07fc750,0x00000007e0800000)
  to   space 2532864K, 0% used [0x00000006ab500000,0x00000006ab500000,0x0000000745e80000)
 ParOldGen       total 8388608K, used 8023076K [0x00000003e0800000, 0x00000005e0800000, 0x00000005e0800000)
  object space 8388608K, 95% used [0x00000003e0800000,0x00000005ca309368,0x00000005e0800000)
 Metaspace       used 139141K, capacity 151323K, committed 151424K, reserved 1183744K
  class space    used 15678K, capacity 17502K, committed 17536K, reserved 1048576K
}

#第1099次gc 【Full GC (Ergonomics) ，这次是个fullgc了 ，花费了 690ms左右】
2024-02-20T17:30:46.888+0800: 21058.374: [Heap Dump (before full gc): , 0.0000775 secs]
{Heap before GC invocations=1099 (full 1):
 PSYoungGen      total 4494848K, used 1171953K [0x00000005e0800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 3322880K, 0% used [0x00000005e0800000,0x00000005e0800000,0x00000006ab500000)
  from space 1171968K, 99% used [0x0000000798f80000,0x00000007e07fc750,0x00000007e0800000)
  to   space 2532864K, 0% used [0x00000006ab500000,0x00000006ab500000,0x0000000745e80000)
 ParOldGen       total 8388608K, used 8023076K [0x00000003e0800000, 0x00000005e0800000, 0x00000005e0800000)
  object space 8388608K, 95% used [0x00000003e0800000,0x00000005ca309368,0x00000005e0800000)
 Metaspace       used 139141K, capacity 151323K, committed 151424K, reserved 1183744K
  class space    used 15678K, capacity 17502K, committed 17536K, reserved 1048576K
2024-02-20T17:30:46.889+0800: 21058.374: [Full GC (Ergonomics) [PSYoungGen: 1171953K->0K(4494848K)] [ParOldGen: 8023076K->2460629K(8388608K)] 9195030K->2460629K(12883456K), [Metaspace: 139141K->137506K(1183744K)], 0.6823041 secs] [Times: user=4.57 sys=6.16, real=0.69 secs] 
Heap after GC invocations=1099 (full 1):
 PSYoungGen      total 4494848K, used 0K [0x00000005e0800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 3322880K, 0% used [0x00000005e0800000,0x00000005e0800000,0x00000006ab500000)
  from space 1171968K, 0% used [0x0000000798f80000,0x0000000798f80000,0x00000007e0800000)
  to   space 2532864K, 0% used [0x00000006ab500000,0x00000006ab500000,0x0000000745e80000)
 ParOldGen       total 8388608K, used 2460629K [0x00000003e0800000, 0x00000005e0800000, 0x00000005e0800000)
  object space 8388608K, 29% used [0x00000003e0800000,0x0000000476af55e8,0x00000005e0800000)
 Metaspace       used 137506K, capacity 148613K, committed 151424K, reserved 1183744K
  class space    used 15423K, capacity 17043K, committed 17536K, reserved 1048576K
}

需要注意：有些监控工具比如prometheus，实际上把上述的Full GC (Ergonomics) 事件在监控上标记成了 Major GC (Ergonomics) 。
为啥呢？下面是gpt的回答：

Q: 
I find that in some monitoring system, like `prometheus`(may be some others), `full gcs` may be labeled as `major gcs` ,why? 
A: 
In some monitoring systems, including Prometheus and others, the terms "full GCs" and "major GCs" may be used 
interchangeably or may both refer to the same type of garbage collection event. This can occur due to 
variations in terminology and terminology conventions across different systems and tools.

The terms "full GC" and "major GC" both generally refer to garbage collection events that involve collecting 
garbage from the entire heap, including both the young and old generations. These events typically occur when 
the JVM determines that a full heap cleanup is necessary, either due to 【high heap occupancy, fragmentation, 
or explicit garbage collection requests】.

While the terms may have slightly different origins or connotations, they are often used synonymously /sɪ
ˈnɒnɪməsli, 同义地/ in practice to describe the same type of garbage collection event. As a result, monitoring 
systems may use either term interchangeably, depending on their specific naming conventions or terminology 
preferences.

It's worth noting that the choice of terminology may also depend on the specific JVM implementation, garbage 
collection algorithm, or documentation conventions followed by the developers of the monitoring system. 
Ultimately, regardless of the terminology used, the important aspect is to understand the nature and impact of 
garbage collection events on application performance and resource utilization

TODO： 更多的关于parallel的

Parallel GC 是java8的默认回收器（注意CMS+ParNew并不是）。