-
Bug
-
Resolution: Fixed
-
P3
-
5.0
Issue | Fix Version | Assignee | Priority | Status | Resolution | Resolved In Build |
---|---|---|---|---|---|---|
JDK-2189337 | 7 | John Cuthbertson | P3 | Closed | Fixed | b85 |
JDK-2190000 | 6u21 | John Cuthbertson | P3 | Resolved | Fixed | b01 |
JDK-2191894 | 6u20-rev | Chris Phillips | P3 | Closed | Fixed | b03 |
JDK-2188167 | 6u19-rev | Chris Phillips | P3 | Closed | Fixed | b07 |
JDK-2185716 | 5.0u23 | Chris Phillips | P3 | Resolved | Fixed | b01 |
JDK-2175175 | hs17 | John Cuthbertson | P3 | Closed | Fixed | b10 |
JDK-2193665 | hs16.3 | Chris Phillips | P3 | Resolved | Fixed | b02 |
JDK-2193521 | hs16.2 | Chris Phillips | P3 | Resolved | Fixed | b07 |
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.
- backported by
-
JDK-2185716 Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate
- Resolved
-
JDK-2190000 Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate
- Resolved
-
JDK-2193521 Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate
- Resolved
-
JDK-2193665 Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate
- Resolved
-
JDK-2175175 Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate
- Closed
-
JDK-2188167 Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate
- Closed
-
JDK-2189337 Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate
- Closed
-
JDK-2191894 Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate
- Closed
- relates to
-
JDK-6852873 Increase in delta between application stopped time and ParNew GC time over application lifetime
- Closed
-
JDK-2189243 Increase in delta between application stopped time and ParNew GC time over application lifetime
- Closed