RFR: 8167190: Remove confusing timestamps from the gc log

[Per Liden]

Hi Erik,

On 10/07/16 10:58, Erik Helin 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.

I welcome this change. These timestamps tends to cause unnecessary 
confusion while adding little value, so removing them seem like the 
right thing to do.

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

Looks good.

cheers,
Per

>
> 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
>