[Understanding] : How to read a G1GC log file.

As a Performance Engineer, time and again you will need to look in to GC logs to see how jvm is handling garbage collection.
With G1GC being the default gc for java versions 9 & above, one needs to know what the G1GC log actually reads like.

To get an understanding of G1GC, here is an in-depth material on it from Oracle tutorials. – link

To begin with, there are 50+ jvm parameters for selecting different GC algorithms and customizing them as per requirement.
Below link has cheat sheet for all the jvm parameters that you can select from. – PDF

For a java application, I enabled G1GC along with below jvm parameters to get details gc logs.

-XX:+UseG1GC" -Xloggc:/data1/gc.log -XX:+PrintGCDetails -XX:+PrintGC

A block of the GC log that was generated out of the application was as below :

 2826.897: [GC pause (G1 Evacuation Pause) (young), 0.0035277 secs]  							
   [Parallel Time: 2.1 ms, GC Workers: 8]														
      [GC Worker Start (ms): Min: 2826897.6, Avg: 2826897.7, Max: 2826897.7, Diff: 0.1]			
      [Ext Root Scanning (ms): Min: 1.1, Avg: 1.2, Max: 1.4, Diff: 0.3, Sum: 9.3]				
      [Update RS (ms): Min: 0.4, Avg: 0.5, Max: 0.6, Diff: 0.2, Sum: 4.3]						
         [Processed Buffers: Min: 2, Avg: 30.4, Max: 74, Diff: 72, Sum: 243]					
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.4]							
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]				
      [Object Copy (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 1.4]						
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]						
         [Termination Attempts: Min: 1, Avg: 1.6, Max: 2, Diff: 1, Sum: 13]						
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]					
      [GC Worker Total (ms): Min: 1.9, Avg: 2.0, Max: 2.0, Diff: 0.1, Sum: 15.7]				
      [GC Worker End (ms): Min: 2826899.6, Avg: 2826899.6, Max: 2826899.7, Diff: 0.0]			
   [Code Root Fixup: 0.0 ms]																	
   [Code Root Purge: 0.0 ms]																	
   [Clear CT: 0.2 ms]																			
   [Other: 1.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 988.0M(988.0M)->0.0B(988.0M) Survivors: 4096.0K->4096.0K Heap: 1312.2M(1656.0M)->324.2M(1656.0M)]   
 [Times: user=0.01 sys=0.00, real=0.00 secs] 

To know how the garbage collector is performing, it is required to read through the above section and make sense out of it. Lets try to understand what each line means.

---

2826.897: [GC pause (G1 Evacuation Pause) (young), 0.0035277 secs]

Evacuation started 2826.89 secs form the start of the java process. GC was triggered in Young region(Eden and survivor). It took an overall 3.5ms for completion of the same.

[Parallel Time: 2.1 ms, GC Workers: 8]

There are 8 GC worker threads – defined by –XX:ParallelGCThreads, which took a 2.1ms of Stop The World (STW) time on parallel tasks from Start of collection till the last GC worker ended.
Side Note: Against the common belief, all the minor GC’s do trigger Stop The World pause. Reference link.

[GC Worker Start (ms): Min: 2826897.6, Avg: 2826897.7, Max: 2826897.7, Diff: 0.1]

The start time of worker threads, in avg, min and max form the start of process.

[Ext Root Scanning (ms): Min: 1.1, Avg: 1.2, Max: 1.4, Diff: 0.3, Sum: 9.3]

The time taken by worker threads scanning the external root(JNI, global, thread stack roots, register) to find the reaches of objects in the collection set.

[Update RS (ms): Min: 0.4, Avg: 0.5, Max: 0.6, Diff: 0.2, Sum: 4.3]

Time taken by worker threads for updating Remember sets.
Remember set(RS) : If a garbage collector does not collect the entire heap (an incremental collection), the garbage collector needs to know where there are pointers from the uncollected part of the heap into the part of the heap that is being collected. This is typically for a generational garbage collector in which the uncollected part of the heap is usually the old generation, and the collected part of the heap is the young generation. The data structure for keeping this information (old generation pointers to young generation objects), is a Remembered set.

[Processed Buffers: Min: 2, Avg: 30.4, Max: 74, Diff: 72, Sum: 243]

This shows how many Update Buffers were processed during Update RS

[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.4]

Time spent for scanning the Remembered set to look for references that point to the regions in the Collection Set.

[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

Time spent in scanning the roots of compiled source code

[Object Copy (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 1.4]

Time spent by worker threads to copy live objects from regions in collection set to new region before the evacuation pause.

[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

After a gc worker completes its work, it enters terminations routine where it syncs with other workers and tries to steal the outstanding worker. This time represents when a worker first tried to terminate and when it actually terminated.

[Termination Attempts: Min: 1, Avg: 1.6, Max: 2, Diff: 1, Sum: 13]

This counts every-time gc worker thread stole the work and re-entered termination state.

[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]		
[GC Worker Total (ms): Min: 1.9, Avg: 2.0, Max: 2.0, Diff: 0.1, Sum: 15.7]	
[GC Worker End (ms): Min: 2826899.6, Avg: 2826899.6, Max: 2826899.7, Diff: 0.0]

GC Worker Other : Time spent performing tasks not accounted in above GC steps.
GC Worker Total : Sum of the time spent by each worker thread on GC.
GC Worker End : The timestamp since the start of JVM when the GC work ended.

[Code Root Fixup: 0.0 ms]
[Clear CT: 0.2 ms]	

Code Root Fixup : Time spent in fixing the roots for objects in collection set with new pointers that may have moved during the GC.
Clear CT : After the garbage collection, purge the entries from code root table.

[Eden: 988.0M(988.0M)->0.0B(988.0M) Survivors: 4096.0K->4096.0K Heap: 1312.2M(1656.0M)->324.2M(1656.0M)]

Reflects how the heap has changed after GC. The young collection was triggered because Eden space was full at 988Mb. After the collection usage on Eden space was reduced to zero bytes. Survivor space was not collected in this cycle. Heap usage overall was reduced from 1312Mb to 324Mb after the GC.

---

Please share your thoughts in the comments section.
Happy tuning!