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

[Per Liden]

On 2015-06-23 10:09, Bengt Rutisson wrote:
>
>
> 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

A few minor suggestions:

concurrentMark.cpp
------------------
2996   if (_has_aborted || !cmThread()->during_cycle()) {

To me it reads better if we first check if it's running before checking 
if it's aborted, i.e.:

if (!cmThread()->during_cycle() || _has_aborted) ...


concurrentMarkThread.cpp
------------------------

   84 void ConcurrentMarkThread::cm_log(bool doit, const char* fmt, ...) {
   85   if (doit) {
   86     SuspendibleThreadSetJoiner sts_joiner;

Could we make all logging in the CM thread use this method? This would 
mean we need another bool argument to tell the sts_joiner to be active 
or not.

/Per

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