Understanding GC Logs - ParadiseGuo/JavaLearning GitHub Wiki

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:

  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: enter image description here

More details can be found in Java Garbage Collection Handbook