Currently the ConcurrentMarkThread in G1 does not take part in the safepoint synchronization for its logging. This means that logging from the concurrent thread can be interleaved with loggging from a normal GC pause:

1,491: #49: [GC concurrent-root-region-scan-start]
1,500: #50: [GC pause (G1 Evacuation Pause) (young)1,501: #49: [GC concurrent-root-region-scan-end, 0,0100111 secs]
1,501: #49: [GC concurrent-mark-start]
, 0,0162226 secs]
   [Root Region Scan Waiting: 1,1 ms]
   [Parallel Time: 6,1 ms, GC Workers: 23]


In the log section above it looks like the root region scanning is completed inside of the G1 evacuation pause and the concurrent mark is started while the pause is running.

This is not really what is happening. In fact the evacuation pause waits for the root region scanning to start before it proceeds with the actual GC work. And the mark tasks that actually do the concurrent marking work will be blocked by the safepoint so, the concurrent marking is not started until after the evacuation pause.

So, apart from being a bit ugly this interleaved logging is actually a bit misleading.

The root region scanning can be fixed by moving the code that waits for the root region scanning to complete to the very start of the evacuation pause. Before any logging from the pause is done.

The other concurrent logging can be fixed by joining the STS before doing the actual logging.

Doing these fixes makes the output look like this:

1,364: #40: [GC concurrent-root-region-scan-start]
1,374: #40: [GC concurrent-root-region-scan-end, 0,0106570 secs]
1,375: #41: [GC pause (G1 Evacuation Pause) (young), 0,0169416 secs]
   [Root Region Scan Waiting: 2,6 ms]
   [Parallel Time: 5,5 ms, GC Workers: 23]
 ...
 [Times: user=0,10 sys=0,00 real=0,02 secs]
1,392: #40: [GC concurrent-mark-start]