RFR: 8167190: Remove confusing timestamps from the gc log

Erik Helin erik.helin at oracle.com
Fri Oct 7 08:58:30 UTC 2016


Hi all,

this patch removes the confusing GC internal timestamps from the GC
logs. Right now, the log looks like the following (with -Xlog:gc*=info):

[19.534s][info][gc,start     ] GC(4) Pause Young (G1 Evacuation Pause) (19.534s)
[19.534s][info][gc,task      ] GC(4) Using 18 workers of 18 for evacuation
[20.133s][info][gc,mmu       ] GC(4) MMU target violated: 201.0ms (200.0ms/201.0ms)
[20.133s][info][gc,phases    ] GC(4)   Evacuate Collection Set: 234.2ms
[20.133s][info][gc,phases    ] GC(4)   Clear Card Table: 0.5ms
[20.133s][info][gc,phases    ] GC(4)   Free Collection Set: 252.6ms
[20.133s][info][gc,phases    ] GC(4)   Expand Heap After Collection: 1.7ms
[20.133s][info][gc,phases    ] GC(4)   Other: 113.6ms
[20.133s][info][gc,heap      ] GC(4) Eden regions: 1463->0(1476)
[20.133s][info][gc,heap      ] GC(4) Survivor regions: 75->62(193)
[20.133s][info][gc,heap      ] GC(4) Old regions: 0->0
[20.133s][info][gc,heap      ] GC(4) Humongous regions: 16->1
[20.133s][info][gc,metaspace ] GC(4) Metaspace: 8328K->8328K(1056768K)
[20.133s][info][gc           ] GC(4) Pause Young (G1 Evacuation Pause) 1554M->62M(1738M) (19.534s, 20.133s) 599.088ms
[20.133s][info][gc,cpu       ] GC(4) User=4.24s Sys=0.08s Real=0.60s

This patch focuses on the timestamps on the lines with "Pause Young":

[19.534s][info][gc,start     ] GC(4) Pause Young (G1 Evacuation Pause) (19.534s)
[20.133s][info][gc           ] GC(4) Pause Young (G1 Evacuation Pause) 1554M->62M(1738M) (19.534s, 20.133s) 599.088ms

The timestamp at the first line, (19.534s), is one (of several) internal
timestamps from the GC code. Almost this exact timestamp is present in
the UL decorator (the timestamp with [19.534]). Furthemore, the GC
timestamp is often confused for being the pause time. The GC internal
timestamps are also present on the second "Pause Young" line, now as a
(begin, end) tuple. Again, this information is already available via the
UL decorators.

Since these GC internal timestamps adds no additional information (but
quite a lot of confusion), this patch removes them.

Webrev:
http://cr.openjdk.java.net/~ehelin/8167190/00/

Bug:
https://bugs.openjdk.java.net/browse/JDK-8167190

Testing:
- JPRT (A few tests that parsed the GC logs had to be updated)

Thanks,
Erik



More information about the hotspot-gc-dev mailing list