RFR: 8167190: Remove confusing timestamps from the gc log

[kirk at kodewerk.com]

Hi Erik,

These time stamps were put in specifically because the time stamps are to guard against skidding between the time of the event and the time that UL will tag the event. This skidding is unlikely to be seen in test environments but we do run into it in production environments. So the comment it adds no additional information is likely only true in testing.

Kind regards,
Kirk

> On Oct 7, 2016, at 10:58 AM, Erik Helin <erik.helin at oracle.com> wrote:
> 
> 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