JEP 271 GC Log Comparison

The table below shows some examples of logs produced by the current (2015-10-26) prototype for JEP 271. For comparison logs with -XX:+PrintGC and -XX:+PrintGCDetails is also provided. It is intended that -Xlog:gc should be similar to -XX:+PrintGC and that -Xlog:gc* should be similar to -XX:+PrintGCDetails.

The logging provided by JEP 271 is much more flexible in its configuration options than the old logging. So, there are many more configurations that can be used to produce logs and control the output. These are just examples and hopefully they show the intent well enough to give an overview.

SerialGC Serial-printgc.txt Serial-printgcdetails.txt Serial-Xlog-gc-info.txt Serial-Xlog-gc-star-info.txt Serial-Xlog-gc-star-debug.txt Serial-Xlog-gc-star-trace.txt
G1 G1-printgc.txt G1-printgcdetails.txt G1-Xlog-gc-info.txt G1-Xlog-gc-star-info.txt G1-Xlog-gc-star-debug.txt G1-Xlog-gc-star-trace.txt
Parallel Parallel-printgc.txt Parallel-printgcdetails.txt Parallel-Xlog-gc-info.txt Parallel-Xlog-gc-star-info.txt Parallel-Xlog-gc-star-debug.txt Parallel-Xlog-gc-star-trace.txt
CMS ConcMarkSweep-printgc.txt ConcMarkSweep-printgcdetails.txt ConcMarkSweep-Xlog-gc-info.txt ConcMarkSweep-Xlog-gc-star-info.txt ConcMarkSweep-Xlog-gc-star-debug.txt ConcMarkSweep-Xlog-gc-star-trace.txt

Some More Details

The logs have been generated by running the TestGCOld test in the HotSpot repo. Instead of running it as a JTreg test, the code was just compiled and run as a stand alone Java program. For the test the same parameters were used as when the test is run with JTreg. Except for with Parallel, the heap was reduced to 128M to make sure we get some old collections. Parallel has some trouble with this test and a small heap. So, the Parallel logs were produced with a 256M heap.

As an example, the Serial-Xlog-gc-star-debug.txt log in the table was produced with this command line:

$ java -Xmx128m -XX:+UseSerialGC -Xlog:gc*=debug -cp test/stress/gc TestGCOld 50 1 20 10 10000

And the Parallel-Xlog-gc-info.txt with this command line:

$ java -Xmx256m -XX:+UseParallelGC -Xlog:gc -cp test/stress/gc TestGCOld 50 1 20 10 10000

Also note that the logs were produced with fastdebug builds. This menas that time measurements in the logs may seem a little high compared to product builds.

Even More Details on the Serial Examples

If you look at the Serial-printgc.txt example you see that GC #3 is missing in the output:

0.231: #0: [GC (Allocation Failure)  34944K->34823K(126720K), 0.4576627 secs]
0.724: #1: [GC (Allocation Failure)  69767K->59139K(126720K), 0.3532928 secs]
1.108: #2: [GC (Allocation Failure)  94083K->60651K(126720K), 0.0919633 secs]
1.212: #4: [Full GC (Allocation Failure)  95595K->61089K(126720K), 0.8269378 secs]

But if you look in Serial-printgcdetails.txt you see this entry:

1.275: #3: [GC (Allocation Failure) 1.275: #3: [DefNew: 36810K->36810K(39296K), 0.0000215 secs]1.275: #4: [Tenured: 58776K->61013K(87424K), 0.8729057 secs] 95587K->61013K(126720K), [Metaspace: 2800K->2800K(1056768K)], 0.8730529 secs] [Times: user=0.87 sys=0.01 real=0.87 secs]

What happened is that a young GC failed and fell over to a full GC. In the PrintGC logging only the full GC was logged.

In the Serial-Xlog-gc-star-info.txt example it is more clear what happens:

[1.300s][info   ][start,gc    ] GC#3 GC (Allocation Failure) DefNew start
[1.300s][info   ][start,gc    ] GC#4 Full GC (Allocation Failure) start
[2.154s][info   ][gc          ] GC#4 Full GC (Allocation Failure) end 93M->59M(123M) (1.300s, 2.154s) 854.130ms
[2.154s][info   ][gc,heap     ] GC#3 def new generation: 36767K->0K(39296K)
[2.154s][info   ][gc,heap     ] GC#3 tenured generation: 58893K->61204K(87424K)
[2.154s][info   ][gc,metaspace] GC#3 Metaspace: 2953K->2953K(1056768K)
[2.154s][info   ][gc          ] GC#3 GC (Allocation Failure) DefNew end 93M->59M(123M) (1.300s, 2.154s) 854.420ms
[2.154s][info   ][gc,cpu      ] GC#3 CPU Times: user=0.85s sys=0.00s real=0.85s

GC #3 is started. It fails and a falls back to a full GC. The full GC is #4 and when it has completed the young GC (#3) can complete and finish up. Basically the full GC is nested inside the young GC. This is pretty much the same as what Serial-printgcdetails.txt was trying to say with its long line. However, a side effect of this is that the -Xlog:gc logging, that only prints the "end" line, it will look like the GCs came in different order. See Serial-Xlog-gc-info.txt:

[0.741s][info   ][gc] GC#0 GC (Allocation Failure) DefNew end 34M->33M(123M) (0.272s, 0.741s) 468.702ms
[1.205s][info   ][gc] GC#1 GC (Allocation Failure) DefNew end 67M->57M(123M) (0.767s, 1.205s) 437.649ms
[1.326s][info   ][gc] GC#2 GC (Allocation Failure) DefNew end 91M->59M(123M) (1.226s, 1.326s) 100.046ms
[2.215s][info   ][gc] GC#4 Full GC (Allocation Failure) end 93M->59M(123M) (1.340s, 2.215s) 874.806ms
[2.215s][info   ][gc] GC#3 GC (Allocation Failure) DefNew end 93M->59M(123M) (1.340s, 2.215s) 874.995ms