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