Has anyone noticed that in JDK 9 the age table in G1 is printed before the GC actually happens? This means that the age table information associated with each GC corresponds to the previous GC. Example:

[2.382s][info][gc,start ] GC(0) Pause Young (G1 Evacuation Pause) (2.382s)
[2.382s][info][gc,task ] GC(0) GC Workers: using 18 out of 18
[2.382s][debug][gc,age ] GC(0) Desired survivor size 895483904 bytes, new threshold 6 (max threshold 6)
## No objects copied to the survivors?
[2.383s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
[2.415s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
[2.415s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
[2.416s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
[2.417s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
[2.417s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
[2.417s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
[2.418s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
[2.419s][info ][gc,phases ] GC(0) Evacuate Collection Set: 32.1ms
[2.419s][info ][gc,phases ] GC(0) Code Roots: 0.0ms
[2.419s][info ][gc,phases ] GC(0) Clear Card Table: 1.5ms
[2.419s][info ][gc,phases ] GC(0) Expand Heap After Collection: 0.0ms
[2.419s][info ][gc,phases ] GC(0) Free Collection Set: 2.0ms
[2.419s][info ][gc,phases ] GC(0) Merge Per-Thread State: 0.1ms
[2.419s][info ][gc,phases ] GC(0) Other: 1.6ms
[2.419s][info ][gc,heap ] GC(0) Eden regions: 2560->0(2553)
[2.419s][info ][gc,heap ] GC(0) Survivor regions: 0->7(427)
## Yes, objects were copied to the survivors...
[2.419s][info ][gc,heap ] GC(0) Old regions: 0->0
[2.419s][info ][gc,heap ] GC(0) Humongous regions: 0->0
[2.419s][info ][gc,metaspace ] GC(0) Metaspace: 6038K->6038K(1056768K)
[2.419s][info ][gc ] GC(0) Pause Young (G1 Evacuation Pause) 10240M->26M(12288M) (2.382s, 2.419s) 37.309ms
[2.419s][info ][gc,cpu ] GC(0) User=0.20s Sys=0.14s Real=0.03s
[3.248s][info ][gc,start ] GC(1) Pause Young (G1 Evacuation Pause) (3.247s)
[3.248s][info ][gc,task ] GC(1) GC Workers: using 18 out of 18
[3.248s][debug][gc,age ] GC(1) Desired survivor size 895483904 bytes, new threshold 6 (max threshold 6)
[3.248s][trace][gc,age ] GC(1) - age 1: 27243352 bytes, 27243352 total
## This is the age table of the previous GC...

The reason for this seems to be that the age table is printed when the tenuring threshold is calculated from the age table (it should be done on a separate call IMHO), which in G1 is done before a GC.


Reported by T. Printezis (http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2016-August/018743.html)