RFR: 8167190: Remove confusing timestamps from the gc log

[Erik Helin]

On 2016-10-07, kirk at kodewerk.com wrote:
> 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.

Hey Kirk, thanks for having a look!

I know about this, that is why I wrote "Almost this exact timestamp is
present in the UL decorator". The problem with taking a timestamp for an
event (e.g. "start of GC") and the event actually happening exists
for the GC internal timestamps as well. The call to Ticks::stamp() that
"sets" the _start_counter in GCTraceTimeImpl will results in a call to
gettimeofday(2) which very well could cause the process to be scheduled
out. Whether that timestamp now is right or wrong depends on when you
consider the GC to "actually start".

If you look at the patch, you will see:
-    out.print_cr(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter));
+    out.cr();

and UL will timestamp the decorator in print_cr (or the call to cr()
after my patch). In almost all cases that will result in the exact same
value as for start_counter. And in the rare case when those two
timetstamps differ then it is my opinion that no timestamp is more
"correct" than the other for when the GC actually started (it depends on
your definition of "start of GC").

On the other hand, if you want to know for how long the Java applicaton
was paused, then you probably want to look at the safepoint logging
(available via the safepoint tag).

Given how confusing these timestamps are for everyone reading the log, I
don't see any value in keeping them.

Thanks,
Erik

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