GC notification oddities

[Ralf Helbing]

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?

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120709/ff3cd587/attachment.html