GC – 3 [ GC Log ] - javartisans

A garbage collection log records data and statistics about Java garbage collection.

It contains all the information to see how the memory cleaning process works.

For instance, it can reveal when GC last ran, how long the process lasted, how much memory was reclaimed, and other useful information.

By analyzing garbage collection logs, we can ensure the Java GC process is effective and quickly identify any potential issues and bottlenecks when it comes to heap memory utilization.

What You Need

About 17 minutes
A favorite text editor or IDE
Java 8 or later

What You Will Learn

1. Activating Simple GC Logging
2. Activating Detailed GC Logging
3. Adding Date and Time Information
4. Logging to a File
5. Tools to Analyze GC Logs

1. Activating Simple GC Logging

We can use -verbose:gc or -XX:+PrintGC to activate the logging of garbage collection information in its simplest form.

Starting with Java 9, it is recommended to use -Xlog:gc instead of -XX:+PrintGC.

According to different garbage collector that we are using, the output is not the same.

Below is an example of using Parallel Garbage Collector :

import java.util.ArrayList;
import java.util.List;

/**
 * -XX:+UseParallelGC
 * -verbose:gc
 * -XX:+PrintGC
 */
public class GCLogTest {
    public static void main(String[] args) {
        List<byte[]> list = new ArrayList<>();

        for (int i = 0; i < 5000; i++) {
            list.add(new byte[1024 * 100]); // 100KB
        }
    }
}

Below is the output of above code snippet :

[0.005s][info][gc] Using Parallel
[0,154s][info][gc] GC(0) Pause Young (Allocation Failure) 63M->61M(240M) 41,976ms
[0,230s][info][gc] GC(1) Pause Young (Allocation Failure) 124M->124M(303M) 65,572ms
[0,283s][info][gc] GC(2) Pause Full (Ergonomics) 124M->124M(405M) 53,658ms
[0,467s][info][gc] GC(3) Pause Young (Allocation Failure) 250M->248M(498M) 98,076ms
[0,538s][info][gc] GC(4) Pause Full (Ergonomics) 248M->248M(703M) 70,128ms
[0,779s][info][gc] GC(5) Pause Young (Allocation Failure) 469M->467M(854M) 163,123ms
[0,871s][info][gc] GC(6) Pause Full (Ergonomics) 467M->467M(1189M) 92,248ms

In the above output, we can already see a lot of useful information about what is going on inside the JVM :

Using Parallel – The type of Garbage Collector.
Pause Young or Pause Full – The type of Garbage Collection, either Young or Full to distinguish a minor or full garbage collection.
(Allocation Failure) or (Ergonomics) – The cause of the collection
Allocation Failure indicates that no more space was left in Eden to allocate objects;
Ergonomics refers to the JVM automatically tuning and deciding when to perform certain GC actions based on the application’s behavior, heap usage, and available resources.
63M->61M – The occupied heap memory before and after the GC.
(240M) – The current capacity of the heap.
41.976 ms – The duration of the GC event in millisecond.

If we take the line, 63M->61M(240M) 41.976ms, it means that the GC reduced the occupied heap memory from 63M to 61M.
The heap capacity at the time of GC was 240M, and the GC took 41.976 milliseconds.

However, although the simple GC logging format can be useful, it provides limited details.

For example, it cannot tell if the GC moved any objects from the young to the old generation or what was the total size of the young generation before and after each collection.

For that reason, detailed GC logging is more useful than the simple one.

2. Activating Detailed GC Logging

We can use -XX:+PrintGCDetails to activate the logging of garbage collection information in its detailed form.

Starting with Java 9, it is recommanded to use -Xlog:gc* instead of-XX:+PrintGCDetails.

Below is an example of detailed gc output of the same test class for Parallel Garbage Collector :

[0.005s][info][gc,init] CardTable entry size: 512
[0.005s][info][gc     ] Using Parallel
[0.006s][info][gc,init] Version: 21.0.3+7-LTS-152 (release)
[0.006s][info][gc,init] CPUs: 6 total, 6 available
[0.006s][info][gc,init] Memory: 15946M
[0.006s][info][gc,init] Large Page Support: Disabled
[0.006s][info][gc,init] NUMA Support: Disabled
[0.006s][info][gc,init] Compressed Oops: Enabled (Zero based)
[0.006s][info][gc,init] Alignments: Space 512K, Generation 512K, Heap 2M
[0.006s][info][gc,init] Heap Min Capacity: 8M
[0.006s][info][gc,init] Heap Initial Capacity: 250M
[0.006s][info][gc,init] Heap Max Capacity: 3988M
[0.006s][info][gc,init] Pre-touch: Disabled
[0.006s][info][gc,init] Parallel Workers: 6
[0.020s][info][gc,metaspace] CDS archive(s) mapped at: [0x00007090bb000000-0x00007090bbca8000-0x00007090bbca8000), size 13271040, SharedBaseAddress: 0x00007090bb000000, ArchiveRelocationMode: 1.
[0.020s][info][gc,metaspace] Compressed class space mapped at: 0x00007090bc000000-0x00007090fc000000, reserved size: 1073741824
[0.020s][info][gc,metaspace] Narrow klass base: 0x00007090bb000000, Narrow klass shift: 0, Narrow klass range: 0x100000000
[0,114s][info][gc,start    ] GC(0) Pause Young (Allocation Failure)
[0,137s][info][gc,heap     ] GC(0) PSYoungGen: 64470K(74752K)->10177K(74752K) Eden: 64470K(64512K)->0K(64512K) From: 0K(10240K)->10177K(10240K)
[0,137s][info][gc,heap     ] GC(0) ParOldGen: 1055K(171008K)->52763K(171008K)
[0,137s][info][gc,metaspace] GC(0) Metaspace: 73K(320K)->73K(320K) NonClass: 70K(192K)->70K(192K) Class: 3K(128K)->3K(128K)
[0,137s][info][gc          ] GC(0) Pause Young (Allocation Failure) 63M->61M(240M) 22,938ms
[0,137s][info][gc,cpu      ] GC(0) User=0,01s Sys=0,08s Real=0,02s
[0,151s][info][gc,start    ] GC(1) Pause Young (Allocation Failure)
[0,275s][info][gc,heap     ] GC(1) PSYoungGen: 74687K(74752K)->10145K(139264K) Eden: 64510K(64512K)->0K(129024K) From: 10177K(10240K)->10145K(10240K)
[0,275s][info][gc,heap     ] GC(1) ParOldGen: 52763K(171008K)->117173K(171008K)
[0,275s][info][gc,metaspace] GC(1) Metaspace: 73K(320K)->73K(320K) NonClass: 70K(192K)->70K(192K) Class: 3K(128K)->3K(128K)
[0,275s][info][gc          ] GC(1) Pause Young (Allocation Failure) 124M->124M(303M) 124,001ms
[0,275s][info][gc,cpu      ] GC(1) User=0,00s Sys=0,50s Real=0,13s
[0,275s][info][gc,start    ] GC(2) Pause Full (Ergonomics)
[0,275s][info][gc,phases,start] GC(2) Marking Phase
[0,336s][info][gc,phases      ] GC(2) Marking Phase 60,855ms
[0,336s][info][gc,phases,start] GC(2) Summary Phase
[0,337s][info][gc,phases      ] GC(2) Summary Phase 0,318ms
[0,337s][info][gc,phases,start] GC(2) Adjust Roots
[0,337s][info][gc,phases      ] GC(2) Adjust Roots 0,540ms
[0,338s][info][gc,phases,start] GC(2) Compaction Phase
[0,433s][info][gc,phases      ] GC(2) Compaction Phase 94,820ms
[0,433s][info][gc,phases,start] GC(2) Post Compact
[0,436s][info][gc,phases      ] GC(2) Post Compact 2,940ms
[0,441s][info][gc,heap        ] GC(2) PSYoungGen: 10145K(139264K)->0K(139264K) Eden: 0K(129024K)->0K(129024K) From: 10145K(10240K)->0K(10240K)
[0,441s][info][gc,heap        ] GC(2) ParOldGen: 117173K(171008K)->127247K(286208K)
[0,441s][info][gc,metaspace   ] GC(2) Metaspace: 73K(320K)->73K(320K) NonClass: 70K(192K)->70K(192K) Class: 3K(128K)->3K(128K)
[0,441s][info][gc             ] GC(2) Pause Full (Ergonomics) 124M->124M(415M) 165,760ms
[0,441s][info][gc,cpu         ] GC(2) User=0,06s Sys=0,51s Real=0,17s
[0,902s][info][gc,start       ] GC(3) Pause Young (Allocation Failure)
[1,961s][info][gc,heap        ] GC(3) PSYoungGen: 129024K(139264K)->10233K(215552K) Eden: 129024K(129024K)->0K(205312K) From: 0K(10240K)->10233K(10240K)
[1,967s][info][gc,heap        ] GC(3) ParOldGen: 127247K(286208K)->244665K(286208K)
[1,967s][info][gc,metaspace   ] GC(3) Metaspace: 73K(320K)->73K(320K) NonClass: 70K(192K)->70K(192K) Class: 3K(128K)->3K(128K)
[1,967s][info][gc             ] GC(3) Pause Young (Allocation Failure) 250M->248M(490M) 1064,764ms
[1,967s][info][gc,cpu         ] GC(3) User=0,00s Sys=5,18s Real=1,06s
[1,967s][info][gc,start       ] GC(4) Pause Full (Ergonomics)
[1,967s][info][gc,phases,start] GC(4) Marking Phase
[2,022s][info][gc,phases      ] GC(4) Marking Phase 55,195ms
[2,023s][info][gc,phases,start] GC(4) Summary Phase
[2,023s][info][gc,phases      ] GC(4) Summary Phase 0,165ms
[2,023s][info][gc,phases,start] GC(4) Adjust Roots
[2,023s][info][gc,phases      ] GC(4) Adjust Roots 0,262ms
[2,023s][info][gc,phases,start] GC(4) Compaction Phase
[2,075s][info][gc,phases      ] GC(4) Compaction Phase 51,151ms
[2,075s][info][gc,phases,start] GC(4) Post Compact
[2,079s][info][gc,phases      ] GC(4) Post Compact 3,901ms
[2,091s][info][gc,heap        ] GC(4) PSYoungGen: 10233K(215552K)->0K(215552K) Eden: 0K(205312K)->0K(205312K) From: 10233K(10240K)->0K(10240K)
[2,092s][info][gc,heap        ] GC(4) ParOldGen: 244665K(286208K)->254870K(495104K)
[2,092s][info][gc,metaspace   ] GC(4) Metaspace: 73K(320K)->73K(320K) NonClass: 70K(192K)->70K(192K) Class: 3K(128K)->3K(128K)
[2,093s][info][gc             ] GC(4) Pause Full (Ergonomics) 248M->248M(694M) 125,962ms
[2,093s][info][gc,cpu         ] GC(4) User=0,05s Sys=0,26s Real=0,13s
[2,642s][info][gc,start       ] GC(5) Pause Young (Allocation Failure)
[3,955s][info][gc,heap        ] GC(5) PSYoungGen: 205312K(215552K)->10226K(363520K) Eden: 205312K(205312K)->0K(353280K) From: 0K(10240K)->10226K(10240K)
[3,955s][info][gc,heap        ] GC(5) ParOldGen: 254870K(495104K)->448300K(495104K)
[3,955s][info][gc,metaspace   ] GC(5) Metaspace: 73K(320K)->73K(320K) NonClass: 70K(192K)->70K(192K) Class: 3K(128K)->3K(128K)
[3,955s][info][gc             ] GC(5) Pause Young (Allocation Failure) 449M->447M(838M) 1312,566ms
[3,955s][info][gc,cpu         ] GC(5) User=0,00s Sys=6,68s Real=1,31s
[3,955s][info][gc,start       ] GC(6) Pause Full (Ergonomics)
[3,955s][info][gc,phases,start] GC(6) Marking Phase
[4,038s][info][gc,phases      ] GC(6) Marking Phase 82,946ms
[4,038s][info][gc,phases,start] GC(6) Summary Phase
[4,038s][info][gc,phases      ] GC(6) Summary Phase 0,025ms
[4,038s][info][gc,phases,start] GC(6) Adjust Roots
[4,038s][info][gc,phases      ] GC(6) Adjust Roots 0,161ms
[4,038s][info][gc,phases,start] GC(6) Compaction Phase
[4,094s][info][gc,phases      ] GC(6) Compaction Phase 55,963ms
[4,094s][info][gc,phases,start] GC(6) Post Compact
[4,100s][info][gc,phases      ] GC(6) Post Compact 6,051ms
[4,119s][info][gc,heap        ] GC(6) PSYoungGen: 10226K(363520K)->0K(363520K) Eden: 0K(353280K)->0K(353280K) From: 10226K(10240K)->0K(10240K)
[4,120s][info][gc,heap        ] GC(6) ParOldGen: 448300K(495104K)->458516K(797184K)
[4,120s][info][gc,metaspace   ] GC(6) Metaspace: 73K(320K)->73K(320K) NonClass: 70K(192K)->70K(192K) Class: 3K(128K)->3K(128K)
[4,120s][info][gc             ] GC(6) Pause Full (Ergonomics) 447M->447M(1133M) 164,497ms
[4,120s][info][gc,cpu         ] GC(6) User=0,07s Sys=0,37s Real=0,16s
[4,132s][info][gc,heap,exit   ] Heap
[4,132s][info][gc,heap,exit   ]  PSYoungGen      total 363520K, used 56627K [0x00000007acf00000, 0x00000007d4780000, 0x0000000800000000)
[4,132s][info][gc,heap,exit   ]   eden space 353280K, 16% used [0x00000007acf00000,0x00000007b064cd60,0x00000007c2800000)
[4,132s][info][gc,heap,exit   ]   from space 10240K, 0% used [0x00000007c2800000,0x00000007c2800000,0x00000007c3200000)
[4,132s][info][gc,heap,exit   ]   to   space 10240K, 0% used [0x00000007d3d80000,0x00000007d3d80000,0x00000007d4780000)
[4,132s][info][gc,heap,exit   ]  ParOldGen       total 797184K, used 458516K [0x0000000706c00000, 0x0000000737680000, 0x00000007acf00000)
[4,132s][info][gc,heap,exit   ]   object space 797184K, 57% used [0x0000000706c00000,0x0000000722bc5000,0x0000000737680000)
[4,132s][info][gc,heap,exit   ]  Metaspace       used 74K, committed 320K, reserved 1114112K
[4,132s][info][gc,heap,exit   ]   class space    used 4K, committed 128K, reserved 1048576K

From above output, it is able to recognize all of the elements from the simple GC log.

But there are several new items, such as :

Size of the young and old generation before and after each GC;
The time it takes for a GC to happen in young and old generation;
The Size of objects promoted at every GC;
A summary of the size of the total heap.

2.1 Interpreting a Minor GC in Young Generation

PSYoungGen: 15331K(17920K)->2496K(17920K) Eden: 15331K(15360K)->0K(15360K) From: 0K(2560K)->2496K(2560K)

Above line represents a minor gc and below is the meaning of each parts :

PSYoungGen : Type of the garbage collection;
15331K(17920K)->2496K(17920K) : Usage of the Young generation before and after collection (The total size of the Young generation);
Eden: 15331K(15360K)->0K(15360K) : Usage of the Eden before and after collection (The total size of the Eden);
From: 0K(2560K)->2496K(2560K) : Usage of the Survivor before and after collection (The total size of the Survivor).

Below line is the duration of the GC event :

User=0.01s Sys=0.03s Real=0.04s

It is measured in different categories :

user – The total CPU time that was consumed by Garbage Collector;
sys – The time spent in OS calls or waiting for system events;
real – This is all elapsed time including time slices used by other processes, the real duration of gc event.

2.2 Interpreting a Major GC in Old Generation

ParOldGen: 27612K(40960K)->30055K(40960K)

Above line represents a major gc and below is the meaning of each parts :

ParOldGen : Type of the garbage collection;
27612K(40960K)->30055K(40960K) : Usage of the Old generation before and after collection (The total size of the Old generation).

2.3 Interpreting a Full GC

Pause Full (Ergonomics) 29M->29M(57M) 24.958ms

Above line represents a full gc and below is the meaning of each parts :

Pause Full (Ergonomics) : Type of the garbage collection;
29M->29M(57M) : Usage of the heap before and after collection (The total size of the heap);
24.958ms : The duration of the GC event.

2.4 Memory Summary

The final part of the output includes a summary of the heap including a memory footprint summary for each part of memory.

[4,132s][info][gc,heap,exit   ] Heap
[4,132s][info][gc,heap,exit   ]  PSYoungGen      total 363520K, used 56627K [0x00000007acf00000, 0x00000007d4780000, 0x0000000800000000)
[4,132s][info][gc,heap,exit   ]   eden space 353280K, 16% used [0x00000007acf00000,0x00000007b064cd60,0x00000007c2800000)
[4,132s][info][gc,heap,exit   ]   from space 10240K, 0% used [0x00000007c2800000,0x00000007c2800000,0x00000007c3200000)
[4,132s][info][gc,heap,exit   ]   to   space 10240K, 0% used [0x00000007d3d80000,0x00000007d3d80000,0x00000007d4780000)
[4,132s][info][gc,heap,exit   ]  ParOldGen       total 797184K, used 458516K [0x0000000706c00000, 0x0000000737680000, 0x00000007acf00000)
[4,132s][info][gc,heap,exit   ]   object space 797184K, 57% used [0x0000000706c00000,0x0000000722bc5000,0x0000000737680000)
[4,132s][info][gc,heap,exit   ]  Metaspace       used 74K, committed 320K, reserved 1114112K
[4,132s][info][gc,heap,exit   ]   class space    used 4K, committed 128K, reserved 1048576K

We can see that Eden space had a 16% footprint and Tenured had a 57% footprint.

A summary for Metadata space and class space is also included.

3. Adding Date and Time Information

It is able to add the following two arguments to get date and time information to appear in gc logs :

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps

Please note that those flags have been removed in Java 9.

The new alternative is :

-Xlog:gc*::time

[2025-07-17T12:27:14.555+0200] CardTable entry size: 512
[2025-07-17T12:27:14.555+0200] Using Parallel
[2025-07-17T12:27:14.557+0200] Version: 21.0.3+7-LTS-152 (release)
[2025-07-17T12:27:14.557+0200] CPUs: 6 total, 6 available
[2025-07-17T12:27:14.557+0200] Memory: 15946M
[2025-07-17T12:27:14.557+0200] Large Page Support: Disabled
[2025-07-17T12:27:14.557+0200] NUMA Support: Disabled
[2025-07-17T12:27:14.557+0200] Compressed Oops: Enabled (Zero based)
[2025-07-17T12:27:14.557+0200] Alignments: Space 512K, Generation 512K, Heap 2M
[2025-07-17T12:27:14.557+0200] Heap Min Capacity: 8M
[2025-07-17T12:27:14.557+0200] Heap Initial Capacity: 250M
[2025-07-17T12:27:14.557+0200] Heap Max Capacity: 3988M
[2025-07-17T12:27:14.557+0200] Pre-touch: Disabled
[2025-07-17T12:27:14.557+0200] Parallel Workers: 6
[2025-07-17T12:27:14.572+0200] CDS archive(s) mapped at: [0x000077310b000000-0x000077310bca8000-0x000077310bca8000), size 13271040, SharedBaseAddress: 0x000077310b000000, ArchiveRelocationMode: 1.
[2025-07-17T12:27:14.572+0200] Compressed class space mapped at: 0x000077310c000000-0x000077314c000000, reserved size: 1073741824
[2025-07-17T12:27:14.572+0200] Narrow klass base: 0x000077310b000000, Narrow klass shift: 0, Narrow klass range: 0x100000000
[2025-07-17T12:27:14.703+0200] Heap
[2025-07-17T12:27:14.703+0200]  PSYoungGen      total 74752K, used 54058K [0x00000007acf00000, 0x00000007b2200000, 0x0000000800000000)
[2025-07-17T12:27:14.703+0200]   eden space 64512K, 83% used [0x00000007acf00000,0x00000007b03cab70,0x00000007b0e00000)
[2025-07-17T12:27:14.703+0200]   from space 10240K, 0% used [0x00000007b1800000,0x00000007b1800000,0x00000007b2200000)
[2025-07-17T12:27:14.703+0200]   to   space 10240K, 0% used [0x00000007b0e00000,0x00000007b0e00000,0x00000007b1800000)
[2025-07-17T12:27:14.703+0200]  ParOldGen       total 171008K, used 1055K [0x0000000706c00000, 0x0000000711300000, 0x00000007acf00000)
[2025-07-17T12:27:14.703+0200]   object space 171008K, 0% used [0x0000000706c00000,0x0000000706d07c08,0x0000000711300000)
[2025-07-17T12:27:14.703+0200]  Metaspace       used 74K, committed 320K, reserved 1114112K
[2025-07-17T12:27:14.703+0200]   class space    used 4K, committed 128K, reserved 1048576K

Each line now starts with the absolute date and time followed by a timestamp reflecting the real-time passed in seconds since the JVM started.

4. Logging to a File

By default the GC log is written to stdout.

A more practical solution is to write to an output file.

It can be done by using the argument -Xloggc:<file> where file is the absolute path to the output file.

For instance, -Xloggc:/path/to/file/gc.log

Ever since Java 9, -Xloggc is deprecated, the alternative for logging to a file is -Xlog:gc:/path/to/file/gc.log

5. Tools to Analyze GC Logs

Depending on the JVM version and the GC algorithm that is used, the GC log format could differ.

So it can be time-consuming and quite tedious to analyze GC logs using a text editor.

There are very good free analysis tools that provide many metrics about potential garbage collection problems, and even potential solutions :

GCViewer : https://github.com/chewiebug/GCViewer/wiki

GCeasy : https://gceasy.io/