Cassandra: An Insights of G1GC log

Share us

This is the third post related to Garbage Collection in Cassandra. In this post we will discuss how to read G1GC log. I have already posted about enabling G1GC log in previous post.

Minor GC Event:-

Whenever a minor GC events occured, gc log prints below. 

2020-03-13T16:15:03.803-0500: 18.259: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 83886080 bytes, new threshold 15 (max 15)
– age 1: 17973160 bytes, 17973160 total
, 0.0291712 secs]
[Parallel Time: 18.4 ms, GC Workers: 18]
[GC Worker Start (ms): Min: 18259.2, Avg: 18259.7, Max: 18263.5, Diff: 4.3]
[Ext Root Scanning (ms): Min: 0.0, Avg: 3.7, Max: 4.2, Diff: 4.2, Sum: 66.9]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Processed Buffers: Min: 0, Avg: 1.1, Max: 8, Diff: 8, Sum: 19]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 1.1, Max: 11.0, Diff: 11.0, Sum: 19.7]
[Object Copy (ms): Min: 2.7, Avg: 12.6, Max: 13.7, Diff: 11.0, Sum: 227.4]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 2.2]
[Termination Attempts: Min: 1, Avg: 8.9, Max: 15, Diff: 14, Sum: 160]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
[GC Worker Total (ms): Min: 13.8, Avg: 17.6, Max: 18.1, Diff: 4.3, Sum: 317.4]
[GC Worker End (ms): Min: 18277.3, Avg: 18277.3, Max: 18277.4, Diff: 0.1]
[Code Root Fixup: 1.5 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 0.5 ms]
[Other: 8.8 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 6.9 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.7 ms]
[Eden: 1192.0M(1192.0M)->0.0B(1160.0M) Survivors: 32.0M->64.0M Heap: 1218.7M(24.0G)->59.9M(24.0G)]
Heap after GC invocations=3 (full 0):
garbage-first heap total 25165824K, used 61294K [0x00000001c0000000, 0x00000001c0806000, 0x00000007c0000000)
region size 8192K, 8 young (65536K), 8 survivors (65536K)
Metaspace used 24274K, capacity 24434K, committed 24700K, reserved 1071104K
class space used 2810K, capacity 2850K, committed 2940K, reserved 1048576K
}
[Times: user=0.32 sys=0.01, real=0.03 secs]

Here, in the above gc log, I have printed the important term in color. Let me explain each term.

2020-03-13T16:15:03.803-0500: 18.259: – It states minor gc event was fired on “2020-03-16T16:15:03:803-0500”. And 18.259 is the time of GC event fired after the JAVA process was started.

GC pause (G1 Evacuation Pause) :- It’s a phase where a live object copied from one region(Young + Old) to another region.

young: – It says it’s the event of Young gc.

GC Workers: 18:- It say no of gc worker thread.

[Eden: 1192.0M(1192.0M)->0.0B(1160.0M) Survivors: 32.0M->64.0M Heap: 1218.7M(24.0G)->59.9M(24.0G)]:- It shows the heap size changes.

  • Eden: 1192.0M(1192.0M)->0.0B(1160.0M) :- It indicates 1192.0M is the size of the Eden gen and all of it occupied. After the event size of it became zero. Capacity of Eden gen has decreased to 1160.0M but yet not committed. Extra capacity was removed as demand has been made.
  • Survivors: 32.0M->64.0M : – It indicates Survivor space was initially 32.0M and after the event it increased to 64.0M. It shows that objects has been promoted from Young gen to survivor space.
  • Heap: 1218.7M(24.0G)->59.9M(24.0G) : – It shows that initially Heap size was 1218.7M out of 24.0G and after the event, objects of size 1158.8M (1218.7M – 59.9M)was garbage collected and heap size became 59.9M out of 24.0G.

[Times: user=0.32 sys=0.01, real=0.03 secs] : – It shows different time, explained below.

  • user=0.32:- It’s the time CPU spent in user-mode code(outside of the kernel) within the process. This is only actual CPU time used in executing the process. Other processes and time the process spends blocked do not count towards this figure.
  • sys=0.01 : – It’s the time CPU spent in the kernel within the process. This means executing CPU time spent in system calls within the kernel, as opposed to library code, which is still running in user-space. Like ‘user’, this is only CPU time used by the process.
  • real=0.03 secs : – It’s the time gc event took to complete it. 

Full GC Event:- 

When a Full gc event occurred, it prints like below.

2020-03-16T04:11:21.703-0600: 19.592: [Full GC (Allocation Failure) 3727M->3612M(4022M), 4.2305359 secs]
[Eden: 928.0M(1160.0M)->0.0B(1128.0M) Survivors: 64.0M->64.0M Heap: 3727.1M(24.0G)->3602.0M(24.0G)], [Metaspace: 277M->277M(1024M)]
[Times: user=9.21, sys=0.01, real=4.23 secs]

Again, I have colored the important term and will explain each of it.

2020-03-16T04:11:21.703-0600: 219.592 : – It’s the gc event occurred at the mentioned time and 219.592 is the time after the Java process this full gc event was fired.

Full GC (Allocation Failure) : – It shows that this even occurred due to allocation failure. When the heap is fragmented, direct allocations in the Old generation may fail even when there is a lot of free space, this will typically cause Allocation Failure

Eden: 928.0M(1160.0M)->0.0B(1128.0M) : – It states that 928.0M is the size of the Eden gen out of 1160.0M. After the event size of it became zero. Capacity of Eden gen has decreased to 1128.0M but yet not committed. Extra capacity was removed as demand has been made.

Survivors: 64.0M->64.0M : – It indicates Survivor space is same before and after the event i.e. 64.0M.

Heap: 3727.1M(24.0G)->3602.0M(24.0G) : – It shows that initially Heap size was 3727.1M out of 24.0G and after the event, objects of size 125.1M (3727.1M – 3602.0M)was garbage collected and heap size became 36.2.0M out of 24.0G.

Metaspace: 277M->277M(1024M) : – It shows that before and after the event size of metaspace was same. Basically, it says Metaspace usage remain consistent in this phase. And the total capacity of it is 1024M.

Rest already explained in Minor GC Event.

Hope, I have explained each and every term of GC log events like Minor/Full GC event.

To get visual insights of G1GC, please visit:- https://gceasy.io/

Reference taken from :- https://blog.gceasy.io/2016/07/07/understanding-g1-gc-log-format/

Still, you can ask questions, comments below.

Leave a Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.