Issue | Fix Version | Assignee | Priority | Status | Resolution | Resolved In Build |
---|---|---|---|---|---|---|
JDK-2220613 | 8 | John Cuthbertson | P4 | Resolved | Fixed | b24 |
JDK-2220549 | 7u4 | John Cuthbertson | P4 | Closed | Fixed | b10 |
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.
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.
- backported by
-
JDK-2220613 G1: Interference from multiple threads in PrintGC/PrintGCDetails output
-
- Resolved
-
-
JDK-2220549 G1: Interference from multiple threads in PrintGC/PrintGCDetails output
-
- Closed
-