Running a simple workload with Serial GC, and waiting it to enter Full GC:
import java.util.*;
public class AL {
static List<Object> l;
public static void main(String... args) throws Throwable {
l = new ArrayList<>();
for (int c = 0; c < 100_000_000; c++) {
l.add(new Object());
}
System.out.println(l.hashCode());
System.in.read();
}
}
$ ~/trunks/jdk-jdk/build/linux-x86_64-server-fastdebug/images/jdk/bin/java -XX:+UseSerialGC -Xlog:gc -Xlog:gc+start AL
Current jdk/jdk prints:
[12.597s][info][gc,start] GC(3) Pause Young (Allocation Failure)
[15.954s][info][gc,start] GC(4) Pause Full (Allocation Failure)
[28.502s][info][gc ] GC(4) Pause Full (Allocation Failure) 1594M->1337M(2130M) 12547.759ms
[28.846s][info][gc ] GC(3) Pause Young (Allocation Failure) 1596M->1337M(3232M) 16249.227ms
There are two problems:
a) GC #3 appears "after" GC #4. "gc+start" does show it started in the correct order, but not everyone has that enabled;
b) Full GC times are counted twice: "young" appears to take 16 seconds, and "full" takes 12 seconds. In reality, "young" finished before "full" started, so it took only ~3 seconds.
The cause is that Full GC collection happens while we are still in Young GC scope. This proof-of-concept patch fixes it:
http://cr.openjdk.java.net/~shade/8215221/webrev.01/
...and logs appears good:
[13.057s][info][gc,start] GC(3) Pause Young (Allocation Failure)
[16.488s][info][gc ] GC(3) Pause Young (Allocation Failure) 1596M->1594M(2130M) 3430.895ms
[16.488s][info][gc,start] GC(4) Pause Full (Allocation Failure)
[29.007s][info][gc ] GC(4) Pause Full (Allocation Failure) 1594M->1337M(2130M) 12519.642ms