United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-8007221 G1: concurrent phase durations do not state the time units ("secs")
JDK-8007221 : G1: concurrent phase durations do not state the time units ("secs")

Details
Type:
Bug
Submit Date:
2013-01-30
Status:
Resolved
Updated Date:
2013-05-06
Project Name:
JDK
Resolved Date:
2013-02-22
Component:
hotspot
OS:
Sub-Component:
gc
CPU:
Priority:
P3
Resolution:
Fixed
Affected Versions:
Fixed Versions:
hs25 (b21)

Related Reports
Backport:
Backport:
Backport:

Sub Tasks

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.
                                     
2013-01-30
URL:   http://hg.openjdk.java.net/hsx/hotspot-gc/hotspot/rev/96c885895d22
User:  johnc
Date:  2013-02-22 23:50:38 +0000

                                     
2013-02-22
URL:   http://hg.openjdk.java.net/hsx/hsx25/hotspot/rev/96c885895d22
User:  amurillo
Date:  2013-03-01 16:29:47 +0000

                                     
2013-03-01



Hardware and Software, Engineered to Work Together