Understanding G1 Garbage Collection Logs

This article focuses on the information G1 GC log printing in the case of the -xx:+printgcdetails option. (Note: This article assumes that the reader has some idea of the basic principles of the G1 algorithm.)

Below is a section of the G1 garbage collector related log information

0.522: [GC Pause (Young), 0.15877971 secs] [Parallel time:157.1 MS] [GC Worker Start (MS): 522.1 522.2 522.2 5   22.2 avg:522.2, min:522.1, max:522.2, diff:0.1] [Ext Root scanning (ms): 1.6 1.5 1.6 1.9 AVG: 1.7, min:1.5, max:1.9, diff:0.4] [Update RS (ms): 38.7 38.8 50.6 37.3 avg:41.3, min:37.3, Max  : 50.6, diff:13.3] [processed Buffers:2 2 3 2 sum:9, Avg:2, Min:2, Max:3, diff:1] [Scan RS (ms): 9.9 9.7 0.0 9.7 avg:7.3, min:0.0, max:9.9, diff:9.9] [Object Copy (ms): 106.7 106.8 1   04.6 107.9 avg:106.5, min:104.6, max:107.9, diff:3.3] [Termination (ms): 0.0 0.0 0.0 0.0 AVG:  0.0, min:0.0, max:0.0, diff:0.0] [termination attempts:1 4 4 6 sum:15, Avg:3, Min:1, Max:      6, Diff:5] [GC Worker End (ms): 679.1 679.1 679.1 679.1 avg:679.1, min:679.1, max:679.1, diff:0.1] [GC Worker (ms): 156.9 157.0 156.9 156.9 avg:156.9, min:156.9, max:157.0, diff:0.1] [GC Worker Other (ms): 0.3 0.3 0. 3 0.3 avg:0.3, min:0.3, max:0.3, diff:0.0] [Clear ct:0.1 ms] [other:1.5 MS] [Choose CSet : 0.0 ms] [ref proc:0.3 MS] [ref enq:0.0 MS] [free cset:0.3 ms] [eden:12m (12M)->0b (10M) Su rvivors:0b->2048k heap:13m (64M)->9739k (64M)] [times:user=0.59 sys=0.02, real=0.16 secs]

The above log is a log of the G1 garbage collector's "tidy pause" phase, where Java objects that are still alive will be copied from the current regions to the new regions.
This is a stop-the-world behavior, and all application threads will stop at a suitable security point.

Let's take a look at the specific meaning of each line of information in the log.

0.522: [GC Pause (Young), 0.15877971 secs]
The finishing Pause phase occurs after the application starts for 0.522 seconds, and the regions involved in grooming is young (if the content inside the parentheses is mixed, it will involve both the young and old areas), which takes 0.15 seconds

[Parallel time:157.1 MS]
Time spent by GC worker threads over the entire phase

[GC Worker Start (ms): 522.1 522.2 522.2 522.2
avg:522.2, min:522.1, max:522.2, diff:0.1]
The point in time at which GC worker threads start working, in MS

[Ext Root Scanning (ms): 1.6 1.5 1.6 1.9
avg:1.7, min:1.5, max:1.9, diff:0.4]
Time spent scanning the extension root node, unit ms

[Update RS (ms): 38.7 38.8 50.6 37.3
avg:41.3, min:37.3, max:50.6, diff:13.3]
The time that the GC worker thread updated the remembered set, and remembered set flags which Java objects are stored in the heap region

[Processed Buffers:2 2 3 2
Sum:9, Avg:2, Min:2, Max:3, Diff:1]
Number of GC worker threads scanning remembered set

[Scan RS (ms): 9.9 9.7 0.0 9.7
avg:7.3, min:0.0, max:9.9, diff:9.9]
Time that GC worker threads spend on remembered set scan

[Object Copy (ms): 106.7 106.8 104.6 107.9
avg:106.5, min:104.6, max:107.9, diff:3.3]
Time spent on object copy

[GC Worker End (ms): 679.1 679.1 679.1 679.1
avg:679.1, min:679.1, max:679.1, diff:0.1]
TIME node for GC worker threads to complete operations

[eden:12m (12M)->0b (13M) survivors:0b->2048k heap:14m (64M)->9739k (64M)]
We give a change in the capacity of each memory area after GC processing, and from the above log we can see that the memory of the Eden area has been fully reclaimed and the target value set by the G1 algorithm is larger.

[times:user=0.59 sys=0.02, real=0.16 secs]
This line records the time statistics for each angle spent in the GC phase, and if the GC time difference between real and the JVM is significant, it indicates that there are other services that consume the resources of the machine

Like the CMS algorithm, the G1 algorithm also has the process of concurrent tagging,

Understanding G1 Garbage Collection Logs