How to properly read some parts of the logging from GC with "-Xlog:heap=debug" "-Xlog:gc=debug"

Question

Suppose I have very simple code:

public class Sandbox { 

    public static void main(String[] args) {

        Map<String, Integer> map = new HashMap<>();

        while (true) {
            map.put(new Random().toString(), new Random().nextInt());
        }
    }
}

It does not matter how "incorrect" it is, but what it does. It produces an OutOfMemory, ultimately. I run it with :

java -Xms50M -Xmx50M "-Xlog:heap*=debug" "-Xlog:gc*=debug" Sandbox

There will be a lot of logging, I will cut them to the most important parts I care about (I also removed some information from some lines for easier reading)

*****************************     GC(0)    *********************************

[0.115s][debug][gc,heap] GC(0) Heap before GC invocations=0 (full 0)
[0.115s][debug][gc,heap] GC(0) region size 1024K, 23 young, 0 survivors

[0.127s][info ][gc,heap] GC(0) Eden regions: 23->0(15)
[0.128s][info ][gc,heap] GC(0) Survivor regions: 0->3(3)
[0.128s][info ][gc,heap] GC(0) Old regions: 0->4
[0.128s][info ][gc,heap] GC(0) Archive regions: 2->2
[0.128s][info ][gc,heap] GC(0) Humongous regions: 1->1

[0.128s][debug][gc,heap] GC(0) Heap after GC invocations=1 (full 0):
[0.128s][debug][gc,heap] GC(0) region size 1024K, 3 young, 3 survivors


 *****************************     GC(1)    *********************************

[0.159s][debug][gc,heap] GC(1) Heap before GC invocations=1 (full 0)
[0.159s][debug][gc,heap] GC(1) region size 1024K, 18 young, 3 survivors

[0.181s][info ][gc,heap] GC(1) Eden regions: 15->0(1)
[0.181s][info ][gc,heap] GC(1) Survivor regions: 3->3(3)
[0.181s][info ][gc,heap] GC(1) Old regions: 4->10
[0.181s][info ][gc,heap] GC(1) Archive regions: 2->2
[0.181s][info ][gc,heap] GC(1) Humongous regions: 3->3

[0.181s][debug][gc,heap] GC(1) Heap after GC invocations=2 (full 0)
[0.181s][debug][gc,heap] GC(1) region size 1024K, 3 young, 3 survivors

*****************************     GC(2)    *********************************

[0.182s][debug][gc,heap] GC(2) Heap before GC invocations=2 (full 0)
[0.182s][debug][gc,heap] GC(2) region size 1024K, 4 young, 3 survivors 

[0.190s][info ][gc,heap] GC(2) Eden regions: 1->0(9)
[0.190s][info ][gc,heap] GC(2) Survivor regions: 3->1(1)
[0.190s][info ][gc,heap] GC(2) Old regions: 10->13
[0.190s][info ][gc,heap] GC(2) Archive regions: 2->2
[0.190s][info ][gc,heap] GC(2) Humongous regions: 3->3

[0.190s][debug][gc,heap] GC(2) Heap after GC invocations=3 (full 0)
[0.190s][debug][gc,heap] GC(2) region size 1024K, 1 young, 1 survivors

What exactly do they mean?

Eugene Eugene · Accepted Answer · 2020-03-06T16:15:34

I have only found two references online that somehow explain this: one here and the other here. Unfortunately, neither of them made much sense, so I had to look at the source code where this is generated to get an understanding.

The first lines:

[0.115s][debug][gc,heap] GC(0) Heap before GC invocations=0 (full 0)
[0.115s][debug][gc,heap] GC(0) region size 1024K, 23 young, 0 survivors

Tell you that before the first invocation of GC (0), young space had 23 regions allocated. It also tells you (indirectly) that out of these 23 : 0 were survivor regions, meaning 23 were Eden ones.

The next lines:

[0.127s][info ][gc,heap] GC(0) Eden     regions:     23 -> 0 (15)
[0.128s][info ][gc,heap] GC(0) Survivor regions:     0  -> 3 (3)

Tell you that before the GC operation, there were 23 Eden regions. All of them were cleared (that 0) (after all, this is the reason young GC exists). Then it shows that before the GC there were 0 Survivor regions, but as the result of this cycle, 3 Survivor Regions were generated.

You have to be extra careful what this means. This does not show you how many regions will be available to the next cycle, this only shows you the transition that happened.

This "transition" is explained in these logs:

[0.128s][debug][gc,heap] GC(0) Heap after GC invocations=1 (full 0):
[0.128s][debug][gc,heap] GC(0) region size 1024K, 3 young, 3 survivors

Notice how the heap has transitioned to 3 young, 3 survivors (thus, 0 eden, all 23 were cleared).

There is another step done afterwards: the total number of regions will be adjusted. How? You can take a look at source code yourself, to find out.

Specifically that (3) will be computed here with more details (and very good comments) here, it basically says how many Survivor Regions will be available to the next GC cycle. In the majority of cases that (3) will be equal to that ->3, for Survivor Regions.

This "adjustment" is about that (15) and (3), which means, the next cycle will have 15 Eden Regions and 3 Survivor Regions; also denoted by the next cycle's logs, at the very beginning of it.

[0.159s][debug][gc,heap] GC(1) Heap before GC invocations=1 (full 0)
[0.159s][debug][gc,heap] GC(1) region size 1024K, 18 young, 3 survivors

There is one comment I need to make here: these are hints to what the GC in the next cycle is suppose to use, they might be ignored (a humongous allocation will cause this, for example).

So we can draw a line now. There are two logical pieces in these logs.

Transition - how young regions changed due to this cycle
Adjust number of young regions after that transition.

Now it should be fairly easy to digest some logs, for example:

[0.182s][debug][gc,heap] GC(2) Heap before GC invocations=2 (full 0)
[0.182s][debug][gc,heap] GC(2) region size 1024K, 4 young, 3 survivors

It started with 4 young = 1 Eden + 3 Survivor

[0.190s][info ][gc,heap] GC(2) Eden     regions: 1 -> 0 (9)
[0.190s][info ][gc,heap] GC(2) Survivor regions: 3 -> 1 (1)

It transitioned to 0 Eden, 1 Survivor

[0.190s][info ][gc,heap] GC(2) Eden     regions: 1 -> 0 (9)
[0.190s][info ][gc,heap] GC(2) Survivor regions: 3 -> 1 (1)

It applied heuristic to generate 9 Eden, 1 Survivor to the next GC cycle.

How to properly read some parts of the logging from GC with "-Xlog:heap*=debug" "-Xlog:gc*=debug"

1 Answers

How to properly read some parts of the logging from GC with "-Xlog:heap=debug" "-Xlog:gc=debug"