Splunk Completes Acquisition of Plumbr Learn more

To blog |

Understanding Garbage Collection Logs

June 4, 2015 by Nikita Salnikov-Tarnovski Filed under: Garbage Collection

This post is the last teaser before we publish the Plumbr GC handbook next week. In this post, we will review how garbage collector logs look like and what useful information one can obtain from them. For this purpose, we have turned on GC logging for a JVM running with -XX:+UseSerialGC by using the following startup parameters:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

This resulted in the output similar to following:

2015-05-26T14:45:37.987-0200: 151.126: [GC (Allocation Failure) 151.126: [DefNew: 629119K->69888K(629120K), 0.0584157 secs] 1619346K->1273247K(2027264K), 0.0585007 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
2015-05-26T14:45:59.690-0200: 172.829: [GC (Allocation Failure) 172.829: [DefNew: 629120K->629120K(629120K), 0.0000372 secs]172.829: [Tenured: 1203359K->755802K(1398144K), 0.1855567 secs] 1832479K->755802K(2027264K), [Metaspace: 6741K->6741K(1056768K)], 0.1856954 secs] [Times: user=0.18 sys=0.00, real=0.18 secs]

The above short snippet from the GC logs exposes a lot of information about what is going on inside the JVM. As a matter of fact, in this snippet there were two Garbage Collection events taking place, one of them cleaning Young generation and the other one taking care of entire heap. Lets look at the first one of these events, a minor GC, taking place in Young generation:

2015-05-26T14:45:37.987-02001:151.1262:[GC3(Allocation Failure4) 151.126: [DefNew5:629119K->69888K6(629120K)7, 0.0584157 secs]1619346K->1273247K8(2027264K)9,0.0585007 secs10][Times: user=0.06 sys=0.00, real=0.06 secs]11

  1. 2015-05-26T14:45:37.987-0200 – Time when the GC event started.
  2. 151.126 – Time when the GC event started, relative to the JVM startup time. Measured in seconds.
  3. GC – Flag to distinguish between Minor & Full GC. This time it is indicating that this was a Minor GC.
  4. Allocation Failure – Cause of the collection. In this case, the GC is triggered due to a data structure not fitting into any region in Young Generation.
  5. DefNew – Name of the garbage collector used. This cryptic name stands for the single-threaded mark-copy stop-the-world garbage collector used to clean Young generation.
  6. 629119K->69888K – Usage of Young generation before and after collection.
  7. (629120K) – Total size of the Young generation.
  8. 1619346K->1273247K – Total used heap before and after collection.
  9. (2027264K) – Total available heap.
  10. 0.0585007 secs – Duration of the GC event in seconds.
  11. [Times: user=0.06 sys=0.00, real=0.06 secs] – Duration of the GC event, measured in different categories:
    • user – Total CPU time that was consumed by Garbage Collector threads during this collection
    • sys – Time spent in OS calls or waiting for system event
    • real – Clock time for which your application was stopped. As Serial Garbage Collector always uses just a single thread, real time is thus equal to the sum of user and system times.

From the above snippet we can understand exactly what was happening with memory consumption inside the JVM during the GC event. Before this collection heap usage totaled at 1,619,346K. Out of this amount, the Young generation consumed 629,119K. From this we can calculate the Old generation usage being equal to 990,227K.

A more important conclusion is hidden in the next batch of numbers, indicating that after the collection young generation usage decreased by 559,231K, but total heap usage decreased only by 346,099K. From this we can again derive that 213,132K of objects had been promoted from Young generation to Old.

This GC event can be illustrated with the following snapshots depicting memory usage right before the GC started and right after it finished:

Serial GC Young Gen Java

If you found the content to be useful, check out the entire Java Garbage Collection Handbook where this example was extracted from.

ADD COMMENT

Comments

Thx

Magneto
Reply

Cool , but where is the code ?

Almas
Reply

Great stuff. Really great explanation

Anoop Sharma
Reply

very helpful

vidya
Reply

Very useful. Cool

Roman
Reply

Very useful..Super

Sudhakar reddy
Reply

This is beautiful done. Thank you so much!!

Merk
Reply

Hello. Thanks for the quick response. I have one more doubt,

Below is my configuration,

wrapper.java.additional.20=-XX:InitialHeapSize=26g
wrapper.java.additional.21=-XX:MaxHeapSize=26g
wrapper.java.additional.25=-XX:NewSize=13g
wrapper.java.additional.26=-XX:MaxNewSize=13g
wrapper.java.additional.28=-XX:MaxTenuringThreshold=9
wrapper.java.additional.29=-XX:SurvivorRatio=5
wrapper.java.additional.38=-XX:CMSInitiatingOccupancyFraction=70
wrapper.java.additional.35=-XX:ParallelGCThreads=6
wrapper.java.additional.36=-XX:ConcGCThreads=3

But the Minor collection is happening when the young gen is not full as per the log(see below), please confirm,

2016-07-01T15:46:25.557-0500: 12247.243: [GC (Allocation Failure) 2016-07-01T15:46:25.557-0500: 12247.243: [ParNew
Desired survivor size 997031936 bytes, new threshold 9 (max 9)
– age 1: 113887376 bytes, 113887376 total
– age 2: 3488976 bytes, 117376352 total
– age 3: 2292184 bytes, 119668536 total
– age 4: 979816 bytes, 120648352 total
– age 5: 808456 bytes, 121456808 total
– age 6: 864312 bytes, 122321120 total
– age 7: 696184 bytes, 123017304 total
– age 8: 698944 bytes, 123716248 total
– age 9: 962952 bytes, 124679200 total
: 9920427K->194932K(11684160K), 0.2673824 secs] 10125378K->400585K(25315648K), 0.2677817 secs] [Times: user=0.37 sys=0.00, real=0.27 secs]

Sam Welson
Reply

Sorry, Sam. Unfortunately, we cannot provide Garbage Collection tuning consulting via our blog. This is not our core business and certainly not the most effective channel.

Nikita
Reply

Thanks, I do understand that. But I just want to know if Minor GC before EDEN getting full is even possible ?

Sam Welson

I have added XX:+PrintTenuringDistribution.

So my output looks like the following,

2016-07-01T15:46:25.557-0500: 12247.243: [GC (Allocation Failure) 2016-07-01T15:46:25.557-0500: 12247.243: [ParNew
Desired survivor size 997031936 bytes, new threshold 9 (max 9)
– age 1: 113887376 bytes, 113887376 total
– age 2: 3488976 bytes, 117376352 total
– age 3: 2292184 bytes, 119668536 total
– age 4: 979816 bytes, 120648352 total
– age 5: 808456 bytes, 121456808 total
– age 6: 864312 bytes, 122321120 total
– age 7: 696184 bytes, 123017304 total
– age 8: 698944 bytes, 123716248 total
– age 9: 962952 bytes, 124679200 total
: 9920427K->194932K(11684160K), 0.2673824 secs] 10125378K->400585K(25315648K), 0.2677817 secs] [Times: user=0.37 sys=0.00, real=0.27 secs]

The maxThreshold is set to 9, I see the memory of the objects for all the 9 ages. This means there are 9 Minor GCs happening ???

Sam Welson
Reply

This output means that at this moment there are objects in the Survival Space that have survived 1 GC cycle, and objects that survived 2 GC cycles etc…

Nikita
Reply

Hello. Thanks for the quick response. I have one more doubt,

Below is my configuration,

wrapper.java.additional.20=-XX:InitialHeapSize=26g
wrapper.java.additional.21=-XX:MaxHeapSize=26g
wrapper.java.additional.25=-XX:NewSize=13g
wrapper.java.additional.26=-XX:MaxNewSize=13g
wrapper.java.additional.28=-XX:MaxTenuringThreshold=9
wrapper.java.additional.29=-XX:SurvivorRatio=5
wrapper.java.additional.38=-XX:CMSInitiatingOccupancyFraction=70
wrapper.java.additional.35=-XX:ParallelGCThreads=6
wrapper.java.additional.36=-XX:ConcGCThreads=3

But the Minor collection is happening when the young gen is not full as per the log(see below), please confirm,

9920427K->194932K(11684160K), 0.2673824 secs] 10125378K->400585K(25315648K), 0.2677817 secs] [Times: user=0.37 sys=0.00, real=0.27 secs]

Sam Welson

great stuff Nikita Salnikov-Tarnovski!

Niraj
Reply

This is great stuff. I am going through the handbook at the moment. I am so excited to learn from your handbook.
Thank you very much.

Sharat
Reply

Hello Nikita Salnikov-Tarnovski!

This is amazing. Very clear and detailed explanation.
I have bookmarked your page.
Would start reading rest of post right now.
Thank you master.

-Venkat Gurram

GurMan
Reply