JDK-7129271 : G1: Interference from multiple threads in PrintGC/PrintGCDetails output
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 7u4
  • Priority: P4
  • Status: Closed
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2012-01-11
  • Updated: 2013-10-04
  • Resolved: 2012-03-24
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
7u4Fixed 8Fixed hs23Fixed
Description
The PrintGC/PrintGCDetails GC pause output during initial mark pauses can see interference from the PrintGC output of the concurrent mark thread. For example:

276.649: [GC pause (young) (initial-mark), 0.59312600 secs]
372.460: [GC pause (young)372.918 (initial-mark), 0.45774300 secs]
3210.137: [GC pause (young)3210.289 (initial-mark), 0.15259300 secs]
3681.914: [GC pause (young) (initial-mark), 0.27059100 secs]
3692.334: [GC pause (young)3692.501 (initial-mark), 0.16728700 secs]
3698.191: [GC pause (young) (initial-mark), 0.14413600 secs]
3705.374: [GC pause (young) (initial-mark), 0.16145600 secs

and:

276.649: [GC pause (young) (initial-mark), 0.59312600 secs]
   [Parallel Time: 575.5 ms]
277.242: [GC concurrent-mark-start]

372.460: [GC pause (young)372.918 (initial-mark), 0.45774300 secs]
: [GC concurrent-mark-start]

3681.914: [GC pause (young) (initial-mark), 0.27059100 secs]
3682.184: [GC concurrent-mark-start]

and:

3210.137: [GC pause (young)3210.289 (initial-mark), 0.15259300 secs]
: [GC concurrent-mark-start] 

3698.191: [GC pause (young) (initial-mark), 0.14413600 secs]
3698.335:    [Parallel Time: 137.2 ms]
[GC concurrent-mark-start]

Most of the time [Parallel Time: comes out as:
3699.247: [GC pause (young), 0.21151000 secs]
   [SATB Drain Time:   0.0 ms]
   [Parallel Time: 166.0 ms]

This seems to happen more frequently when the GC logging output is directed to a file using the -Xloggc:<file> flag rather than when it is directed to stdout.

The irregularity and randomness of the output makes it difficult to parse.

Comments
EVALUATION http://hg.openjdk.java.net/lambda/lambda/hotspot/rev/7ca7be5a6a0b
22-03-2012

EVALUATION http://hg.openjdk.java.net/hsx/hotspot-gc/hotspot/rev/7ca7be5a6a0b
19-01-2012

SUGGESTED FIX Move the signaling of the CM thread until after the GC pause log output has been completed.
11-01-2012

EVALUATION Interference between output VM thread (GC pause logging output) and CM thread because both are running in parallel. Move the signaling of the CM thread until after the GC pause log output has been completed.
11-01-2012