Review request (S): 7176220: 'Full GC' events miss date stamp information occasionally

[Bengt Rutisson]

Hi Andreas,

I think this looks good. I like that we treat PrintGCDateStamps and 
PrintGCTimeStamps in a consistent way.

One thing that kind of worries me is that the TraceTime class is used 
from other parts of the JVM than just the GC. This means that you now 
get date stamps on compiler events if you enable PrintGCDateStamps. I 
think this is probably fine since they already get time stamps if you 
enable PrintGCTimeStamps. See for example how PhaseTraceTime is used in C1.

Maybe we should send this review out on hotspot-dev to make sure that 
all teams have a chance to comment on this?

Thanks,
Bengt

On 2012-09-28 12:01, Andreas Eriksson wrote:
> Hi,
>
> Can I have some reviews for the following change please:
> http://cr.openjdk.java.net/~brutisso/7176220/webrev.00/ 
> <http://cr.openjdk.java.net/%7Ebrutisso/7176220/webrev.00/>
>
> This fixes GC logs from genCollectedHeap.cpp where sometimes it would 
> not print date-stamps.
> The fix moves printing of date-stamps into TraceTime, where 
> time-stamps are already printed from.
>
> Bug with flags -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -verbose:gc 
> -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps:
> 2012-09-28T11:41:38.687+0200: 0.205: [Full GC 8702K->1012K(9920K), 
> 0.0108630 secs]
> 1.253: [Full GC 3326K->1012K(9920K), 0.0105750 secs]
> 2.299: [Full GC 7932K->1012K(9920K), 0.0100470 secs]
> 2012-09-28T11:41:41.813+0200: 3.331: [Full GC 8702K->1012K(9920K), 
> 0.0103210 secs]
>
> Another route that was investigated was to add the date-stamp call 
> directly in genCollectedHeap.cpp, but because of complex interactions 
> when a full GC was initiated from a non-full GC this path was not taken.
>
>
> This will slightly change the logging output when using 
> -XX:+PrintGCDetails.
> Now date-stamps will also be printed inside other lines, as 
> time-stamps already are:
>
> Before:
> 2012-09-28T11:29:16.815+0200: 0.177: [GC0.177: [ParNew: 
> 2710K->46K(3072K), 0.0053590 secs] 3480K->1835K(9920K), 0.0055500 
> secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
>
> After:
> 2012-09-28T11:29:33.260+0200: 0.184: [GC2012-09-28T11:29:33.261+0200: 
> 0.184: [ParNew: 2642K->45K(3072K), 0.0095770 secs] 
> 3412K->1828K(9920K), 0.0097520 secs] [Times: user=0.01 sys=0.00, 
> real=0.01 secs]
>
> Thanks to Bengt Rutisson for helping with the change and webrev.
>
> Regards,
> Andreas

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20121002/db0d8953/attachment.htm>