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