Understanding G1 Log

Understanding G1 Log

To understand the log, this section defines a number of terms using actual GC log output. The following examples show output from the log with explanations of the terms and values you will find in it.

Note: For more information check out Poonam Bajaj’s Blog post on G1 GC logs.

G1 Logging Terms Index

Clear CT
CSet
External Root Scanning
Free CSet
GC Worker End
GC Worker Other
Object Copy
Other
Parallel Time
Ref Eng
Ref Proc
Scanning Remembered Sets
Termination Time
Update Remembered Set
Worker Start
Parallel Time

414.557: [GC pause (young), 0.03039600 secs] [Parallel Time: 22.9 ms]
[GC Worker Start (ms): 7096.0 7096.0 7096.1 7096.1 706.1 7096.1 7096.1 7096.1 7096.2 7096.2 7096.2 7096.2
Avg: 7096.1, Min: 7096.0, Max: 7096.2, Diff: 0.2]
Parallel Time – Overall elapsed time of the main parallel part of the pause
Worker Start – Timestamp at which the workers start
Note: The logs are ordered on thread id and are consistent on each entry

External Root Scanning

[Ext Root Scanning (ms): 3.1 3.4 3.4 3.0 4.2 2.0 3.6 3.2 3.4 7.7 3.7 4.4
Avg: 3.8, Min: 2.0, Max: 7.7, Diff: 5.7]
External root scanning - The time taken to scan the external root (e.g., things like system dictionary that point into the heap.)

Update Remembered Set

[Update RS (ms): 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Avg: 0.0, Min: 0.0, Max: 0.1, Diff: 0.1]
[Processed Buffers : 26 0 0 0 0 0 0 0 0 0 0 0
Sum: 26, Avg: 2, Min: 0, Max: 26, Diff: 26]
Update Remembered Set - Any buffers that are completed but have not yet been processed by the concurrent refinement thread before the start of the pause have to be updated. Time depends on density of the cards. The more cards, the longer it will take.

Scanning Remembered Sets

[Scan RS (ms): 0.4 0.2 0.1 0.3 0.0 0.0 0.1 0.2 0.0 0.1 0.0 0.0 Avg: 0.1, Min: 0.0, Max: 0.4, Diff: 0.3]F
Scanning Remembered Sets - Look for pointers that point into the Collection Set.

Object Copy

[Object Copy (ms): 16.7 16.7 16.7 16.9 16.0 18.1 16.5 16.8 16.7 12.3 16.4 15.7 Avg: 16.3, Min: 12.3, Max: 18.1, Diff: 5.8]
Object copy – The time that each individual thread spent copying and evacuating objects.

Termination Time

[Termination (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
0.0 Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0] [Termination Attempts : 1 1 1 1 1 1 1 1 1 1 1 1 Sum: 12, Avg: 1, Min: 1, Max: 1, Diff: 0]
Termination time - When a worker thread is finished with its particular set of objects to copy and scan, it enters the termination protocol. It looks for work to steal and once it’s done with that work it again enters the termination protocol. Termination attempt counts all the attempts to steal work.

GC Worker End

[GC Worker End (ms): 7116.4 7116.3 7116.4 7116.3 7116.4 7116.3 7116.4 7116.4 7116.4 7116.4 7116.3 7116.3
Avg: 7116.4, Min: 7116.3, Max: 7116.4, Diff: 0.1]
[GC Worker (ms): 20.4 20.3 20.3 20.2 20.3 20.2 20.2 20.2 20.3 20.2 20.1 20.1
Avg: 20.2, Min: 20.1, Max: 20.4, Diff: 0.3]
GC worker end time – Timestamp when the individual GC worker stops.

GC worker time – Time taken by individual GC worker thread.

GC Worker Other

[GC Worker Other (ms): 2.6 2.6 2.7 2.7 2.7 2.7 2.7 2.8 2.8 2.8 2.8 2.8
Avg: 2.7, Min: 2.6, Max: 2.8, Diff: 0.2]
GC worker other – The time (for each GC thread) that can’t be attributed to the worker phases listed previously. Should be quite low. In the past, we have seen excessively high values and they have been attributed to bottlenecks in other parts of the JVM (e.g., increases in the Code Cache occupancy with Tiered).

Clear CT

[Clear CT: 0.6 ms]
Time taken to clear the card table of RSet scanning meta-data

Other

[Other: 6.8 ms]
Time taken for various other sequential phases of the GC pause.

CSet

[Choose CSet: 0.1 ms]
Time taken finalizing the set of regions to collect. Usually very small; slightly longer when having to select old.

Ref Proc

[Ref Proc: 4.4 ms]
Time spent processing soft, weak, etc. references deferred from the prior phases of the GC.

Ref Enq

[Ref Enq: 0.1 ms]
Time spent placing soft, weak, etc. references on to the pending list.

Free CSet

[Free CSet: 2.0 ms]
Time spent freeing the set of regions that have just been collected, including their remembered sets.

ref :
Tuning JVM Garbage Collection for Production Deployments
Understanding G1 GC Logs
Getting Started with the G1 Garbage Collector