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

[Bengt Rutisson]

Hi Per,

Thanks for looking at this!

On 2015-06-23 11:17, Per Liden wrote:
> 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.

Good points.

Here's an updated webrev:
http://cr.openjdk.java.net/~brutisso/8129549/webrev.01/

Here's a diff compared to the first version:
http://cr.openjdk.java.net/~brutisso/8129549/webrev.00-01.diff/

Thanks,
Bengt
>
> /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