JDK-6782663 : Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 5.0
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • OS: solaris_9
  • CPU: sparc
  • Submitted: 2008-12-09
  • Updated: 2017-05-16
  • Resolved: 2010-02-03
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other Other JDK 6 JDK 7 Other
5.0u22-rev,hs16.2Fixed 5.0u23Fixed 6u19-revFixed 7Fixed hs16.2Fixed
Related Reports
Relates :  
Relates :  
Description
OPERATING SYSTEM:
Data gathered on Solaris 10 (may apply to others)

FULL JDK VERSION:
All

DESCRIPTION:
The time data produced when the options PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime are enabled is not always accurate when compared to the GC timestamps - the two sets of values often disagree by a significant margin. This prevents accurate analysis of application and GC performance.

The problem exists with 1.4.2 and 5.0 JREs, but the problem seems to be most pronounced with the parallel collectors on 5.0. Here is an example from 5.0:

...
348692.751: [GC 348692.751: [ParNew: 252339K->6510K(286720K), 0.0321036 secs] 513266K->267444K(1372160K), 0.0324390 secs]
  Total time for which application threads were stopped: 0.0355259 seconds
Application time: 45.6524701 seconds
349097.447: [GC 349097.447: [ParNew: 252270K->6741K(286720K), 0.0368750 secs] 513204K->267683K(1372160K), 0.0372196 secs]
...

Application stopped time: 0.0355259 seconds
Application time: 45.6524701 seconds
=> the total time between the two GC cycles according to these values was 45.688 seconds.

But the GC timestamps indicate that the time between the two cycles was 404.696 seconds (348692.751 - 349097.447). The two calcuations disagree by 359.008, or nearly six minutes!

In the same run lasting several days we saw the following:

Disagreement  | number    | % of all GC
 (seconds)    | of cases  | cycles (2381)
-----------------------------------------
   > 400      |    2      |   0.08%
   > 300      |    11     |   0.46%
   > 200      |    26     |   1.09%
   > 100      |    39     |   1.64%
   > 50       |    53     |   2.23%
   > 25       |    97     |   4.07%
   > 10       |    220    |   9.24%
   > 5        |    267    |   11.21%
   > 2        |    301    |   12.64%
   > 1        |    454    |   19.06%
   > 0.1      |    680    |   28.56%
   > 0.01     |    787    |   33.05%

So nearly 20% of the event timings disagreed by at least a second. The usefulness of the information is seriously reduced by this level of inaccuracy.

Comments
EVALUATION ChangeSet=http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/8859772195c6,ChangeRequest=6782663
10-02-2010

EVALUATION Per John Cuthebertson: Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate. The information reported by the flags PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is incorrect and inconsistent. In the output it appears that there are sizeable chunks of unattributed time. Two new runtime flags are added as replacements for these flags, which have been deprecated, that measure and display the application execution time between all safepoint types (not just safepoints for GC events) and the duration of the safepoints themselves. [See below These were not used : -XX:+PrintInterSafepointIntervals -XX:+PrintSafepointDurations ] Note : In the process of the resolution of the issue, it was decided that the above mentioned flags would _NOT_ be introduced. So the previous flags were used to provide the improved accuracy of timings: -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime
23-07-2009