JDK-8007221 : G1: concurrent phase durations do not state the time units ("secs")
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2013-01-30
  • Updated: 2013-09-18
  • Resolved: 2013-02-22
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.
JDK 7 JDK 8 Other
7u40Fixed 8Fixed hs24Fixed
Description
A report from Ramki:
-----
Hi John, all -- 

I'm using 7u9, perhaps this has been fixed subsequently. Here's an example of the missing units (and the inconsistency):-

The young and mixed pauses print duration units of "secs" :-

2013-01-30T01:46:45.652-0800: 9522.134: [GC pause (young), 1.10620800 secs]
2013-01-30T01:47:03.563-0800: 9540.045: [GC pause (young), 0.90593900 secs]
2013-01-30T01:47:18.619-0800: 9555.101: [GC pause (young), 0.81425400 secs]
2013-01-30T01:47:59.536-0800: 9596.018: [GC pause (young), 0.84935400 secs]
2013-01-30T01:48:12.097-0800: 9608.579: [GC pause (young) (initial-mark), 0.50153600 secs]
2013-01-30T01:48:59.189-0800: 9655.671: [GC pause (young), 0.02815400 secs]
2013-01-30T01:51:53.952-0800: 9830.457: [GC pause (mixed), 0.66860800 secs]
2013-01-30T01:53:20.704-0800: 9917.186: [GC pause (mixed), 0.47479200 secs]
2013-01-30T01:54:41.098-0800: 9997.579: [GC pause (mixed), 0.72149500 secs]
2013-01-30T01:55:58.944-0800: 10075.426: [GC pause (young), 0.32158300 secs]


The concurrent phases are often missing the units, but not always (mark phase duration prints "sec", others are mum):-

2013-01-30T01:12:10.711-0800: 7447.193: [GC concurrent-root-region-scan-end, 1.0222980]
2013-01-30T01:12:41.386-0800: 7477.868: [GC concurrent-mark-end, 30.6749800 sec]
2013-01-30T01:12:41.626-0800: 7478.108: [GC concurrent-cleanup-end, 0.0063520]
2013-01-30T01:24:18.588-0800: 8175.070: [GC concurrent-root-region-scan-end, 0.5868510]
2013-01-30T01:25:01.089-0800: 8217.571: [GC concurrent-mark-end, 42.5016130 sec]
2013-01-30T01:25:01.321-0800: 8217.803: [GC concurrent-cleanup-end, 0.0057450]
2013-01-30T01:36:27.063-0800: 8903.545: [GC concurrent-root-region-scan-end, 0.3746230]
2013-01-30T01:37:18.642-0800: 8955.124: [GC concurrent-mark-end, 51.5794260 sec]
2013-01-30T01:37:18.869-0800: 8955.351: [GC concurrent-cleanup-end, 0.0048270]
2013-01-30T01:48:13.162-0800: 9609.644: [GC concurrent-root-region-scan-end, 0.5630820]
2013-01-30T01:48:55.513-0800: 9651.995: [GC concurrent-mark-end, 42.3504330 sec]
2013-01-30T01:48:55.769-0800: 9652.251: [GC concurrent-cleanup-end, 0.0041170]

Would be nice to have it be consistent across G1 and indeed across all collectors, if not already the case. Also makes for more consistent parsing of logs.
-----

Indeed a very recent G1 log shows the same problem:

0.572: [GC concurrent-root-region-scan-start]
0.573: [GC concurrent-root-region-scan-end, 0.0014220]
0.573: [GC concurrent-mark-start]
0.575: [GC concurrent-mark-end, 0.0019130 sec]

It looks like a couple of prints in concurrentMarkThread.cpp are missing the units.

I'll check the other collectors to see if any of the GC output is missing units.

Comments
Missing units in GC log print statements.
30-01-2013