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 the review!

Bengt

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