Full GC

After understanding how Parallel GC cleans the Young Generation, we are ready to look at how the whole heap is being cleaned by analyzing the next snippet from the GC logs:

2015-05-26T14:27:41.155-02001:116.3562:[Full GC3 (Ergonomics4)[PSYoungGen: 1305132K->0K(2796544K)]5[ParOldGen6:7133794K->6597672K 7(8388608K)8] 8438926K->6597672K9(11185152K)10, [Metaspace: 6745K->6745K(1056768K)] 11, 0.9158801 secs12, [Times: user=4.49 sys=0.64, real=0.92 secs]13

  1. 2015-05-26T14:27:41.155-0200 – Time when the GC event started
  2. 116.356 – Time when the GC event started, relative to the JVM startup time. Measured in seconds. In this case we can see the event started right after the previous Minor GC finished.
  3. Full GC – Flag indicating that the event is Full GC event cleaning both the Young and Old generations.
  4. Ergonomics – Reason for the GC taking place. This indicates that the JVM internal ergonomics decided this is the right time to collect some garbage.
  5. [PSYoungGen: 1305132K->0K(2796544K)] – Similar to previous example, a parallel mark-copy stop-the-world garbage collector named “PSYoungGen” was used to clean the Young Generation. Usage of Young Generation shrank from 1305132K to 0, which is the typical result of a Full GC.
  6. ParOldGen – Type of the collector used to clean the Old Generation. In this case, parallel mark-sweep-compact stop-the-world garbage collector named ParOldGen was used.
  7. 7133794K->6597672K – Usage of the Old Generation before and after the collection
  8. (8388608K) – Total size of the Old Generation
  9. 8438926K->6597672K – Usage of the whole heap before and after the collection.
  10. (11185152K) – Total heap available
  11. [Metaspace: 6745K->6745K(1056768K)] – Similar information about Metaspace region. As we can see, no garbage was collected in Metaspace during this event.
  12. 0.9158801 secs – Duration of the GC event in seconds
  13. [Times: user=4.49 sys=0.64, real=0.92 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. With Parallel GC this number should be close to (user time + system time) divided by the number of threads used by Garbage Collector. In this particular case 8 threads were used. Note that due to some activities not being parallelizable, it always exceeds the ratio by a certain amount.

Again, the difference with Minor GC is evident – in addition to the Young Generation, during this GC event the Old Generation and Metaspace were also cleaned. The layout of the memory before and after the event would look like the situation in the following picture:

ParallelGC Java

Plumbr exposes this information

Reading the raw text-form GC logs is quite like looking for a needle in a haystack. If a long GC pause happened in your application, but no user was affected by it, is it even worth the effort to fix it? Getting this information from the GC logs is hard and unreliable. Plumbr, however, exposes the impact of the GC pauses, so you only have to worry about them if the user experience is suffering.

Read more