United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-7129271 G1: Interference from multiple threads in PrintGC/PrintGCDetails output
JDK-7129271 : G1: Interference from multiple threads in PrintGC/PrintGCDetails output

Details
Type:
Enhancement
Submit Date:
2012-01-11
Status:
Closed
Updated Date:
2013-10-04
Project Name:
JDK
Resolved Date:
2012-03-24
Component:
hotspot
OS:
generic
Sub-Component:
gc
CPU:
generic
Priority:
P4
Resolution:
Fixed
Affected Versions:
7u4
Fixed Versions:
hs23 (b12)

Related Reports
Backport:
Backport:

Sub Tasks

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
SUGGESTED FIX

Move the signaling of the CM thread until after the GC pause log output has been completed.
                                     
2012-01-11
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.
                                     
2012-01-11
EVALUATION

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

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



Hardware and Software, Engineered to Work Together