Wrong "Application time" log

[Rainer Jung]

Hello,

today I noticed a strange error in the output produced by 
"-XX:+PrintGCApplicationConcurrentTime
". Sometimes it prints a duration that is much to short (sometimes about 
50% of the real timje, sometimes about 1/100 of the correct duration). I 
can't see a pattern, when it prints the correct value and when not. I've 
never noticed this before, so I have the feeling it might be related to 
the relative new 1.5 version used.

I don't bother that much about the wrong Application time, but more 
whether the same might be tue for other durations logged, like the 
stopped time.

Version: 1.5.0_16 für Linux 64 Bits

Flags:

-server
-Xms4096m
-Xmx4096m
-XX:NewSize=768m
-XX:MaxNewSize=768m
-XX:SurvivorRatio=6
-XX:PermSize=128m
-XX:ParallelGCThreads=4
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-verbose:gc
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
-XX:+PrintGCTimeStamps
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCApplicationStoppedTime

Logfile Excerpt:


16.12.2008 12:48:59 1631.157: [GC {Heap before gc invocations=72:
16.12.2008 12:48:59  par new generation   total 688128K, used 590917K 
[0x00002aabb2ab0000, 0x00002aabe2ab0000, 0x00002aabe2ab0000)
...
16.12.2008 12:48:59 1631.157: [ParNew
16.12.2008 12:48:59 Desired survivor size 50331648 bytes, new threshold 
15 (max 15)
16.12.2008 12:48:59 - age   1:   12681720 bytes,   12681720 total
16.12.2008 12:48:59 - age   2:      26280 bytes,   12708000 total
16.12.2008 12:48:59 : 590917K->12447K(688128K), 0.0256140 secs] 
2238509K->1660039K(4096000K)Heap after gc invocations=73:
16.12.2008 12:48:59  par new generation   total 688128K, used 12447K 
[0x00002aabb2ab0000, 0x00002aabe2ab0000, 0x00002aabe2ab0000)
...
16.12.2008 12:48:59 }
16.12.2008 12:48:59 , 0.0259310 secs]
16.12.2008 12:48:59 Total time for which application threads were 
stopped: 0.0463160 seconds

OK, so this happened at start+1631.157.

!!!

16.12.2008 12:49:42 Application time: 0.4276880 seconds


!!!

And now (see below) we are at start+1673.793, which is 42.636 seconds later.
The system runs very performant, so there is no external stop for 42 
seconds.

16.12.2008 12:49:42 1673.793: [GC {Heap before gc invocations=73:
16.12.2008 12:49:42  par new generation   total 688128K, used 602271K 
[0x00002aabb2ab0000, 0x00002aabe2ab0000, 0x00002aabe2ab0000)
...
16.12.2008 12:49:42 1673.793: [ParNew
16.12.2008 12:49:42 Desired survivor size 50331648 bytes, new threshold 
1 (max 15)
16.12.2008 12:49:42 - age   1:   91587848 bytes,   91587848 total
16.12.2008 12:49:42 - age   2:    9042360 bytes,  100630208 total
16.12.2008 12:49:42 : 602271K->98304K(688128K), 0.4321040 secs] 
2249863K->1836598K(4096000K)Heap after gc invocations=74:
16.12.2008 12:49:42  par new generation   total 688128K, used 98304K 
[0x00002aabb2ab0000, 0x00002aabe2ab0000, 0x00002aabe2ab0000)
...
16.12.2008 12:49:42 }
16.12.2008 12:49:42 , 0.4323710 secs]
16.12.2008 12:49:42 Total time for which application threads were 
stopped: 0.4349240 seconds

The additional timestamps in front of each line come from an external 
program we pipe STDOUT through. That is stable since very long time, and 
the discrepancies are already between the JVM internal figures.

Any ideas why this happens?

Regards,

Rainer
-- 
kippdata
informationstechnologie GmbH   Tel: +49 228 98549 -0
Bornheimer Str. 33a            Fax: +49 228 98549 -50
D-53111 Bonn                   www.kippdata.de

HRB 8018 Amtsgericht Bonn / USt.-IdNr. DE 196 457 417
Geschäftsführer: Dr. Thomas Höfer, Rainer Jung, Sven Maurmann