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.
|