GC notification oddities

[John Cuthbertson]

Hi Ralf,

There are somethings that occur during the safepoint that the GC times 
may not take in to account (for example TLAB retirement) but may be 
included in the GC notification durations. I'd have to look at the code 
to determine the full list. How do the GC times and the durations in the 
GC notifications compare against the output from 
-XX:+PrintGCApplicationStoppedTime?

JohnC

On 7/9/2012 11:15 AM, Ralf Helbing wrote:
>
> dear mailing list,
>
> I just started to play with GC notifications based on /Jack Shirazi/s 
> example code from http://www.fasterj.com/articles/gcnotifs.shtml. What 
> seems odd is that the reported durations do not match those from plain 
> old GC logging.
> So I get this output from GC notifications:
>
> 2012-07-09 20:04:24    SYSTEM    memory    IQMemoryWatcher.java:303    
> -    Young Gen GC: - 2 ParNew (from Allocation Failure) 4,435,157 us / 
> 4,435,157
> 2012-07-09 20:04:24    SYSTEM    memory    IQMemoryWatcher.java:332    
> -    Par Eden Space (fully expanded) used: 100.0% -> 0.0% (1MB) / CMS 
> Old Gen (still expandable) used: 0.0% -> 0.0% (1MB) / CMS Perm Gen 
> (fully expanded) used: 19.1% -> 19.1% (50MB) / Code Cache (still 
> expandable) used: 99.2% -> 99.2% (18MB) / Par Survivor Space (fully 
> expanded) used: 4.1% -> 99.1% (407MB) /
> 2012-07-09 20:04:24    SYSTEM    memory    IQMemoryWatcher.java:337    
> -    GC cumulated overhead 0.4%, total duration: 4,643,408 us
>
> 2012-07-09 20:04:43    SYSTEM    memory    IQMemoryWatcher.java:303    
> -    Young Gen GC: - 3 ParNew (from Allocation Failure) 97,168,327 us 
> / 97,168,327
> 2012-07-09 20:04:43    SYSTEM    memory    IQMemoryWatcher.java:332    
> -    Par Eden Space (fully expanded) used: 100.0% -> 0.0% (1MB) / CMS 
> Old Gen (still expandable) used: 0.0% -> 22660.0% (1190MB) / CMS Perm 
> Gen (fully expanded) used: 19.5% -> 19.5% (51MB) / Code Cache (still 
> expandable) used: 99.2% -> 99.2% (20MB) / Par Survivor Space (fully 
> expanded) used: 99.1% -> 100.0% (410MB) /
> 2012-07-09 20:04:43    SYSTEM    memory    IQMemoryWatcher.java:337    
> -    GC cumulated overhead 7.4%, total duration: 101,811,735 us
>
> and at the same time in GC.log
>
> 2012-07-09T20:04:24.106+0200: 77.960: [GC 77.960: [ParNew: 
> 3373086K->415951K(3774912K), 0.3097769 secs] 
> 3373086K->415951K(3780288K), 0.3098689 secs] [Times: user=3.31 
> sys=0.61, real=0.31 secs]
> 2012-07-09T20:04:35.746+0200: 89.600: [GC 89.600: [ParNew: 
> 3771471K->419392K(3774912K), 6.7863811 secs] 
> 3771471K->1637595K(5002044K), 6.7866131 secs] [Times: user=40.70 
> sys=3.45, real=6.79 secs]
> 2012-07-09T20:04:42.533+0200: 96.387: [GC [1 CMS-initial-mark: 
> 1218203K(1227132K)] 1711538K(5002044K), 0.6360475 secs] [Times: 
> user=0.64 sys=0.00, real=0.64 secs]
> […]
>
> which seems more plausible. In the first line of each notification, we 
> report the GCInfo#duration(), along with the difference between 
> #endTime() and #startTime(), which seems to match, but without any 
> relation to wall clock or CPU time.
> Unfortunately, there is no real documentation about time units 
> reported by GCInfo.
>
> I used 1.7.0_05 64bit, Windows.
>
> What am I doing wrong?
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120709/b8095d5d/attachment.html