Detailed analysis of GC logs, ParallelGC and G1

1, ParallelGC: default garbage collector

jvm startup parameters:

-XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/tmp/heapdump.hprof 
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-Xloggc:/tmp/gc-%t.log

GC log:

OpenJDK 64-Bit Server VM (25.282-b08) for bsd-amd64 JRE (1.8.0_282-b08), built on Jan 20 2021 11:47:40 by "jenkins" with gcc 4.2.1 Compatible Apple LLVM 10.0.1 (clang-1001.0.46.4)
Memory: 4k page, physical 16777216k(1307840k free)
 
/proc/meminfo:
 
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof -XX:InitialHeapSize=268435456 -XX:+ManagementServer -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2021-11-01T19:40:51.674+0800: 0.784: [GC (Allocation Failure) [PSYoungGen: 65536K->8101K(76288K)] 65536K->8117K(251392K), 0.0058830 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
2021-11-01T19:40:51.995+0800: 1.104: [GC (Allocation Failure) [PSYoungGen: 73637K->10732K(76288K)] 73653K->11331K(251392K), 0.0097180 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
2021-11-01T19:40:52.089+0800: 1.198: [GC (Metadata GC Threshold) [PSYoungGen: 26096K->6926K(76288K)] 26694K->7533K(251392K), 0.0049565 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-11-01T19:40:52.094+0800: 1.203: [Full GC (Metadata GC Threshold) [PSYoungGen: 6926K->0K(76288K)] [ParOldGen: 606K->6641K(101376K)] 7533K->6641K(177664K), [Metaspace: 20192K->20192K(1067008K)], 0.0274601 secs] [Times: user=0.13 sys=0.00, real=0.03 secs] 
2021-11-01T19:40:52.622+0800: 1.731: [GC (Allocation Failure) [PSYoungGen: 65536K->7830K(109056K)] 72177K->14480K(210432K), 0.0060188 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 
2021-11-01T19:40:53.167+0800: 2.277: [GC (Metadata GC Threshold) [PSYoungGen: 94371K->10737K(139264K)] 101020K->17917K(240640K), 0.0065412 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
2021-11-01T19:40:53.174+0800: 2.283: [Full GC (Metadata GC Threshold) [PSYoungGen: 10737K->0K(139264K)] [ParOldGen: 7180K->16648K(172544K)] 17917K->16648K(311808K), [Metaspace: 33567K->33567K(1079296K)], 0.0669463 secs] [Times: user=0.45 sys=0.01, real=0.07 secs] 

The GC log information is analyzed in detail below.  

Young GC: GC (Allocation Failure)

2021-11-01T19:40:51.674+0800: 0.784: [GC (Allocation Failure) [PSYoungGen: 65536K->8101K(76288K)] 65536K->8117K(251392K), 0.0058830 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 

 1. 2021-11-01T19:40:51.674+0800: 0.784

Execution timestamp + time zone + jvm start to current time (seconds)

2. GC (Allocation Failure) 

GC: garbage collection.         

Allocation Failure: the younger generation does not have enough space to store new objects.

3. [PSYoungGen: 65536K->8101K(76288K)] 65536K->8117K(251392K), 0.0058830 secs

PSYoungGen: the name of the garbage collector used.

65536K - > 8101k (76288k): pre GC size of young generation - > post GC size of young generation (total size of young generation)

65536K - > 8117k (251392k): heap size before GC - > heap size after GC (total heap size, including young and old generations)

0.0058830 secs: time of this GC, Sec

4. [Times: user=0.02 sys=0.01, real=0.01 secs]

Time: time spent in user mode + time spent in kernel mode + real total time spent (indicating that GC is executed concurrently by multiple threads)

Young GC: GC (Metadata GC Threshold)

2021-11-01T19:40:52.089+0800: 1.198: [GC (Metadata GC Threshold) [PSYoungGen: 26096K->6926K(76288K)] 26694K->7533K(251392K), 0.0049565 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

The repeated part will not be repeated.

Metadata GC Threshold: perform GC when the meta space reaches the threshold.

Possible reasons for Metadata GC Threshold: - XX:MetaspaceSize default value 21M causes GC caused by insufficient meta space, so the jvm startup parameter must display the declaration - XX:MetaspaceSize size, overwriting the default value.

-XX:MetaspaceSize=512M

Full GC (Metadata GC Threshold)

2021-11-01T19:40:52.094+0800: 1.203: [Full GC (Metadata GC Threshold) [PSYoungGen: 6926K->0K(76288K)] [ParOldGen: 606K->6641K(101376K)] 7533K->6641K(177664K), [Metaspace: 20192K->20192K(1067008K)], 0.0274601 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]

1. Full GC (Metadata GC Threshold)

Full GC: full GC, including young generation, old generation and meta space.

2. [ParOldGen: 606K->6641K(101376K)] 7533K->6641K(177664K)

ParOldGen: the name of the garbage collector used.

606k - > 6641k (101376k): pre GC size of the aged generation - > post GC size of the aged generation (total size of the aged generation).

7533k - > 6641k (177664k): heap size before GC - > heap size after GC (total heap size, including young and old generations).

3. [Metaspace: 20192K->20192K(1067008K)]

Meta space: size before GC - > size after GC (total size of meta space)

Full GC (Heap Inspection Initiated GC)

2021-11-01T21:01:33.217+0800: 4842.275: [GC (Heap Inspection Initiated GC) [PSYoungGen: 76271K->5961K(164352K)] 92919K->22681K(336896K), 0.0302703 secs] [Times: user=0.06 sys=0.07, real=0.03 secs] 
2021-11-01T21:01:33.248+0800: 4842.305: [Full GC (Heap Inspection Initiated GC) [PSYoungGen: 5961K->0K(164352K)] [ParOldGen: 16720K->15373K(229376K)] 22681K->15373K(393728K), [Metaspace: 39135K->38916K(1085440K)], 0.1303204 secs] [Times: user=0.42 sys=0.09, real=0.13 secs] 

Heap inspection initiated GC: Full GC caused by jmap -histo:live command   GC.

Full GC (Heap Dump Initiated GC)

2021-11-02T10:52:48.703+0800: 1189.751: [Full GC (Heap Dump Initiated GC) [PSYoungGen: 438K->0K(4608K)] [ParOldGen: 13507K->13335K(13824K)] 13945K->13335K(18432K), [Metaspace: 40906K->40901K(1087488K)], 0.0482085 secs] [Times: user=0.33 sys=0.00, real=0.05 secs]

Execute jmap - dump: FullGC triggered by live.

Full GC (System.gc())

2021-11-02T10:46:04.307+0800: 785.354: [Full GC (System.gc()) [PSYoungGen: 867K->0K(4608K)] [ParOldGen: 13691K->13507K(13824K)] 14559K->13507K(18432K), [Metaspace: 40906K->40906K(1087488K)], 0.0937626 secs] [Times: user=0.68 sys=0.00, real=0.10 secs]

When - XX:+DisableExplicitGC is not configured, the FullGC triggered by code System.gc().

Full GC (Ergonomics)

2021-11-02T10:35:25.797+0800: 146.844: [Full GC (Ergonomics) [PSYoungGen: 2521K->0K(4608K)] [ParOldGen: 13138K->13222K(13824K)] 15659K->13222K(18432K), [Metaspace: 39515K->39515K(1085440K)], 0.0205221 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 

Ergonomics: "Ergonomics", which means adaptive adjustment in jvm. Useadaptive sizepolicy is enabled by default. The jvm automatically mediates the balance between gc pause time and throughput, and adaptively adjusts the full gc caused.

default   The ParallelGC collector combination (Parallel Scavenge + Parallel Old) in Server mode will make a judgment before Minor GC, that is, the memory space allocation guarantee mechanism:

Before Eden space shortage occurs in Minor GC, the virtual machine first checks whether the maximum available continuous space of the elderly generation is greater than the total space of all objects of the new generation. If the conditions are true, Minor GC can confirm that it is safe. If not, the virtual machine checks whether the value of HandlePromotionFailure allows guarantee failure. If yes, check whether the maximum available continuous space of the elderly generation is greater than the average size of objects promoted to the old age. If greater than, it will continue to try Minor GC. If the value less than or HandlePromotionFailure does not allow risk taking, a Full GC will be performed.

However, JDK7 and later HandlePromotionFailure will fail. The rule becomes: MinorGC is performed as long as the continuous space of the old age is greater than the total size of the objects of the new generation or the average size of the objects promoted to the old age, otherwise FullGC is performed.

Parallel Scavenge is a collector focusing on throughput: the goal of Parallel Scavenge is to achieve a controllable throughput. Throughput = program running time / (program running time + GC time). For example, if the program runs for 99s, GC takes 1s, and throughput = 99 / (99 + 1) = 99%. Parallel Scavenge provides two parameters to accurately control throughput, namely - XX:MaxGCPauseMillis to control the maximum GC pause time and - XX:GCTimeRatio to directly control throughput.

Manually trigger Full GC

jmap -histo:live PID | head -50

or 

jmap -histo:live PID | more

or

jmap -dump:format=b,live,file=heapdump.hprof PID

View GC statistics

jstat -gc pid

// For GC statistics, focus on the last five parameters: YGC, YGCT, FGC, FGCT and GCT
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
13312.0 13312.0  0.0    0.0   151040.0  1290.0   229376.0   15373.1   41728.0 38916.3 5632.0 5133.5      6    0.063   3      0.225    0.288

Garbage collector G1

jvm startup parameters:

-Xms100m  
-Xmx100m  
-XX:MetaspaceSize=512M  
-XX:MaxDirectMemorySize=1024M 
-Xss256k 
-XX:+UseG1GC  
-XX:MaxGCPauseMillis=200 
-XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/tmp/heapdump.hprof 
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-Xloggc:/tmp/gc-%t.log 
-Duser.timezone=Asia/Shanghai  
-Dfile.encoding=UTF-8

GC pause (G1 Evacuation Pause) (young)

2021-11-02T18:03:27.713+0800: 0.523: [GC pause (G1 Evacuation Pause) (young), 0.0035728 secs]
   [Parallel Time: 2.0 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 523.0, Avg: 523.1, Max: 523.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 1.4, Diff: 1.3, Sum: 3.2]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [Object Copy (ms): Min: 0.5, Avg: 1.5, Max: 1.7, Diff: 1.2, Sum: 14.8]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 25.6, Max: 35, Diff: 34, Sum: 256]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 1.8, Avg: 1.9, Max: 1.9, Diff: 0.1, Sum: 18.8]
      [GC Worker End (ms): Min: 524.9, Avg: 524.9, Max: 524.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 24576.0K(24576.0K)->0.0B(36864.0K) Survivors: 0.0B->3072.0K Heap: 24576.0K(100.0M)->3466.0K(100.0M)]
 [Times: user=0.02 sys=0.00, real=0.00 secs] 

The overall structure is extracted as follows:

GC pause (G1 Evacuation Pause) (young)    // Total time of this GC
  ├── Parallel Time    // GC thread parallel recycling time consuming
    ├── GC Worker Start      
    ├── Ext Root Scanning    // Time consuming to scan root threads
    ├── Update RS            // Update RS 
    ├── Scan RS              // Scan RS                
    ├── Code Root Scanning   // Root scan time
    ├── Object Copy          // Object Copy 
    ├── GC Worker Other      // GC thread other time consuming
    ├── GC Worker Total      // Total GC thread time
    ├── GC Worker End    
  ├── Code Root Fixup
  ├── Code Root Purge
  ├── Clear CT       // Clearing the CardTable takes time. RS is an object that depends on the survival of the CardTable record area
  ├── Other          // Other time consuming
    ├── Choose CSet         // Select CSet
    ├── Ref Proc            // The processing of weak references and soft references takes time
    ├── Ref Enq             // Queue time for weak references and soft references
    ├── Redirty Cards
    ├── Humongous Register
    ├── Humongous Reclaim
    ├── Free CSet           // Time consuming to release recycled areas

G1 young GC process summary:

G1 young GC total time = GC thread parallel recovery time  +  Clearing CardTable takes time + other time.

The following conclusions can be drawn from the GC log data above:

1. The total GC time is mainly spent on   GC thread parallel recovery time and   Others take these two stages.

two   GC thread parallel recovery time is mainly spent on   Scanning the root thread takes two stages: time and object copy.

three    Other time-consuming time is mainly spent in the reference processing stage.

Summary: the total GC time is mainly spent on   There are three small stages: the time spent scanning the root thread, the object copy, and the time spent processing references.

The GC log of G1 is analyzed in detail below.

2021-11-02T18:03:27.713+0800: 0.523: [GC pause (G1 Evacuation Pause) (young), 0.0035728 secs]

Execution date + time zone + Jvm start time (seconds) + GC pause + G1 evacuation pause + young generation GC + total consumed time (seconds).

G1 evaluation pause: G1 evacuation is suspended, and the surviving objects are copied to one or more regions. The target Region may be Young area, Young area + Old area, depending on whether YGC has objects eligible for promotion to Old area this time.

[Parallel Time: 2.0 ms, GC Workers: 10]

The concurrent execution time of GC threads is 2.0ms + the number of concurrent GC threads is 10.

[Clear CT: 0.1 ms]

It takes 0.1ms to empty the CardTable.

[Other: 1.5 ms]

Others take 1.5ms.

[Eden: 24576.0K(24576.0K)->0.0B(36864.0K) Survivors: 0.0B->3072.0K Heap: 24576.0K(100.0M)->3466.0K(100.0M)]

Eden area: size before GC (total size before GC) - > size after GC (total size after GC)

Survivors area: size before GC - > size after GC

Heap area: size before GC (total size before GC) - > size after GC (total size after GC)

[Times: user=0.02 sys=0.00, real=0.00 secs]

User space time + kernel space time + real GC time

GC pause (G1 Humongous Allocation) (young)(initial-mark)

2021-11-18T17:43:33.112+0800: 433.473: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0094487 secs]
   [Parallel Time: 7.6 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 433473.5, Avg: 433473.6, Max: 433473.7, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.7, Avg: 0.8, Max: 0.9, Diff: 0.2, Sum: 7.7]
      [Update RS (ms): Min: 0.4, Avg: 1.2, Max: 3.7, Diff: 3.3, Sum: 11.9]
         [Processed Buffers: Min: 1, Avg: 2.1, Max: 3, Diff: 2, Sum: 21]
      [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 2.7, Avg: 5.0, Max: 5.9, Diff: 3.2, Sum: 50.1]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.0]
         [Termination Attempts: Min: 1, Avg: 160.1, Max: 195, Diff: 194, Sum: 1601]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 7.2, Avg: 7.3, Max: 7.4, Diff: 0.1, Sum: 72.8]
      [GC Worker End (ms): Min: 433480.9, Avg: 433480.9, Max: 433480.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.9 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 12288.0K(31744.0K)->0.0B(29696.0K) Survivors: 5120.0K->5120.0K Heap: 66134.6K(100.0M)->56382.0K(100.0M)]
 [Times: user=0.07 sys=0.00, real=0.01 secs] 
2021-11-18T17:43:33.121+0800: 433.482: [GC concurrent-root-region-scan-start]
2021-11-18T17:43:33.123+0800: 433.484: [GC concurrent-root-region-scan-end, 0.0018936 secs]
2021-11-18T17:43:33.123+0800: 433.484: [GC concurrent-mark-start]
2021-11-18T17:43:33.135+0800: 433.496: [GC concurrent-mark-end, 0.0118927 secs]
2021-11-18T17:43:33.135+0800: 433.496: [GC remark 2021-11-18T17:43:33.135+0800: 433.496: [Finalize Marking, 0.0002043 secs] 2021-11-18T17:43:33.135+0800: 433.497: [GC ref-proc, 0.0016572 secs] 2021-11-18T17:43:33.137+0800: 433.498: [Unloading, 0.0039254 secs], 0.0061435 secs]
 [Times: user=0.03 sys=0.00, real=0.01 secs] 
2021-11-18T17:43:33.142+0800: 433.503: [GC cleanup 58301K->43965K(100M), 0.0008515 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-11-18T17:43:33.142+0800: 433.504: [GC concurrent-cleanup-start]
2021-11-18T17:43:33.142+0800: 433.504: [GC concurrent-cleanup-end, 0.0000188 secs]

G1 Full GC process summary:

G1 Full GC total time = initial marking time (young GC)  +  Parallel root area scanning takes time+   Concurrent marking time+   Retag time+   Concurrent cleanup takes time.

Parallel root area scanning and   Re tagging requires stop world, but root area scanning and   The time-consuming proportion of re tagging is relatively low. The Full GC of G1 is mainly spent in the initial tagging and concurrent tagging stages. This is also the embodiment of the better recovery performance of G1.

The GC log is analyzed in detail below.

[GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0094487 secs]

GC pause + G1 huge (object) allocation + young generation GC + initial marking + consumption time of 9.4ms.

G1 Humongous Allocation: if an object exceeds half of a single Region space, it will be regarded as a giant object by G1, and the giant object will be directly allocated to the Humongous area in the old age. If the Region contains giant objects, the space between the last giant object in the Region and the end of the Region will not be used. If all the huge objects are just a little larger than the regional constraints, these unused space will cause the heap to become fragmented. If there are a large number of GC triggered by Humongous Allocation, a large number of memory fragments may be formed in the old age. Solution: add - XX:G1HeapRegionSize, that is, make the object less than 50% of the Region, so that the previous large objects are no longer directly allocated to the Humongous area, but follow the conventional object allocation method.

Initial mark: the initial mark is synchronized with the young GC, so it is also called the first recycling.

[GC concurrent-root-region-scan-start]

The scan of the GC parallel root area begins.

[GC concurrent-root-region-scan-end, 0.0014241 secs]

GC   The scanning of the parallel root area was completed, taking 1.4ms

[GC concurrent-mark-start]

GC concurrency flag start.

[GC concurrent-mark-end, 0.0163857 secs]

GC concurrent marking ends, taking 16.3ms.

[GC remark 2021-11-18T17:43:34.676+0800: 435.037: [Finalize Marking, 0.0006953 secs] 2021-11-18T17:43:34.676+0800: 435.037: [GC ref-proc, 0.0013824 secs] 2021-11-18T17:43:34.678+0800: 435.039: [Unloading, 0.0036554 secs], 0.0059840 secs]

GC relabel     Timestamp: [final marking, time consuming] + timestamp: [GC reference - processing, time consuming] + timestamp: [unloading, time consuming] + total time consuming 5.9ms.

[GC cleanup 52836K->47961K(100M), 0.0006854 secs]

GC cleanup    The heap size before cleaning is 52.8m - > the heap size after cleaning is 47.9m (total size 100M), taking 0.6ms.

[GC concurrent-cleanup-start]

GC concurrent cleanup started.

[GC concurrent-cleanup-end, 0.0000113 secs]

GC concurrent cleanup ends, taking 0.01ms.

GC pause (G1 Evacuation Pause) (mixed)

2021-11-18T17:43:35.098+0800: 435.459: [GC pause (G1 Evacuation Pause) (mixed), 0.0130780 secs]
   [Parallel Time: 11.6 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 435459.4, Avg: 435459.5, Max: 435459.5, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.8, Diff: 0.7, Sum: 2.5]
      [Update RS (ms): Min: 1.0, Avg: 1.4, Max: 1.6, Diff: 0.6, Sum: 14.2]
         [Processed Buffers: Min: 2, Avg: 2.6, Max: 4, Diff: 2, Sum: 26]
      [Scan RS (ms): Min: 1.4, Avg: 1.6, Max: 2.1, Diff: 0.8, Sum: 15.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.5]
      [Object Copy (ms): Min: 7.6, Avg: 8.1, Max: 8.4, Diff: 0.8, Sum: 81.4]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
         [Termination Attempts: Min: 1, Avg: 140.2, Max: 177, Diff: 176, Sum: 1402]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 11.5, Avg: 11.5, Max: 11.6, Diff: 0.1, Sum: 115.2]
      [GC Worker End (ms): Min: 435471.0, Avg: 435471.0, Max: 435471.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 1024.0K(1024.0K)->0.0B(4096.0K) Survivors: 6144.0K->1024.0K Heap: 51938.3K(100.0M)->47228.9K(100.0M)]
 [Times: user=0.12 sys=0.01, real=0.02 secs] 

[GC pause (G1 Evacuation Pause) (mixed), 0.0130780 secs]

GC pause + G1 evacuation pause + mixed mode (i.e. Full GC) + the total time is 13ms.

Total mixed GC time=   Thread parallel recycling time + clearing CardTable time + other time (reference processing time).

[GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0091829 secs]

[GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0068124 secs]

Memory fragmentation caused by too many giant objects causes G1 to space exhausted.

To space: the survivor area of the younger generation.

Posted on Mon, 22 Nov 2021 06:09:41 -0500 by ss32