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

[Bengt Rutisson]

Thanks for the reviews, Thomas and Per!

Bengt


On 2015-06-24 12:47, Per Liden wrote:
> On 2015-06-23 14:47, Bengt Rutisson wrote:
>>
>> Hi Thomas and Per,
>>
>> I noticed that there is still a problem with the root-region-end logging
>> in my webrev.01 version.
>>
>> We notified that the root region had finished before we did the "end"
>> logging. Thus that last log line could still end up interleaved with the
>> evacuation pause logging.
>>
>> I discussed a few different solutions with Per and StefanK and finally
>> we settled on simply moving the logging in inside of
>> ConcurrentMark::scanRootRegions().
>>
>> Here's an updated webrev:
>> http://cr.openjdk.java.net/~brutisso/8129549/webrev.02/
>> http://cr.openjdk.java.net/~brutisso/8129549/webrev.01-02.diff/
>
> Looks good.
>
> /Per
>
>>
>> Thanks,
>> Bengt
>>
>> On 2015-06-23 12:34, Bengt Rutisson wrote:
>>>
>>> Hi Thomas,
>>>
>>> Thanks for looking at this!
>>>
>>> On 2015-06-23 11:42, Thomas Schatzl wrote:
>>>> Hi Bengt,
>>>>
>>>> On Tue, 2015-06-23 at 10:09 +0200, 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
>>>>>
>>>>>   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]
>>>> Seems okay except for some minor tidbit that you may ignore: in
>>>> ConcurrentMark.cpp:3019: I would prefer if the message contained
>>>> "ConcurrentMark::" as there might be multiple methods called abort. Of
>>>> course, hopefully the stack trace shows the method. Really not sure.
>>>
>>> Good point. I'll add "ConcurrentMark::" to the assert message before I
>>> push.
>>>
>>> Thanks for the review!
>>> Bengt
>>>
>>>> Thanks,
>>>>    Thomas
>>>>
>>>>
>>>
>>