RFR (S): JDK-8129549 G1: Make sure the concurrnet thread does not mix its logging with the STW pauses

[Bengt Rutisson]

Hi everyone,

Could I have a couple of reviews for this patch?

http://cr.openjdk.java.net/~brutisso/8129549/webrev.00/
https://bugs.openjdk.java.net/browse/JDK-8129549

 From the bug report:

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]


Thanks,
Bengt