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

[Per Liden]

Hi Bengt,

On 2015-06-23 11:16, Bengt Rutisson wrote:
>
> 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/

Looks good!

cheers,
/Per

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