RFR(s): 8068344: G1GC concurrent marking time report is not accurate

[sangheon]

Hi Thomas and Bengt,

Okay, I withdraw this proposal.

Because 3/4 of this CR's complains are due to misunderstanding or 
already fixed and following enhancement will address these issues.
#1: misunderstanding of the log and there's a problem with the 
elapsedVTime measurement but this is different from the CR.
#2(not updating '_init_mark'): not critical and this can be resolved by 
following enhancement.
#3: misunderstanding of the log
#4: already fixed.

For some reason I just got Thomas' other email.

Thanks,
Sangheon

On 04/07/2016 03:43 AM, Bengt Rutisson wrote:
>
> Hi Sangheon and Thomas,
>
> FWIW, I am fine with just closing JDK-8068344 as will not fix and then 
> file an RFE to implement better concurrent timing the way Thomas 
> suggested at the end of his email.
>
> Thanks,
> Bengt
>
> On 2016-04-07 12:18, Thomas Schatzl wrote:
>> Hi,
>>
>> On Wed, 2016-04-06 at 15:48 -0700, sangheon wrote:
>>> Hi all,
>>>
>>> Please review this change to enhance G1 concurrent mark time report.
>>>
>>> This patch includes 2 changes.
>>> 1. Include cleanup time at virtual time of ConcurrentMarkThread
>>> class:
>>> Looking at the comment, cleanup was expected to be small enough to be
>>> ignored but actually it isn't. And this CR is requesting to include
>>> it.
>> Two issues with that change:
>>
>> - why does the ConcurrentMarkThread thread get vtime by accumulating
>> parts of the whole time? Os::elapsedVTime() already gives you the total
>> cpu time spent in that thread which seems to be what _vtime_accum tries
>> to "calculate".
>>
>> It would be sufficient to regularly assign os::elapsedVTime() to
>> _vtime_accum imo.
>>
>> - due to that, the tracking at the moment does not consider half of its
>> operation, only marking and some random other parts. Why not concurrent
>> cleanup? Why not the cleanup work for the next mark?
>>
>> That does not make any sense.
>>
>> - the time span added (what you consider "cleanup time") should really
>> be really small, and this change kind of superfluous. The
>> ConcurrentMarkThread itself does not participate in the actual cleanup
>> work, it only starts the Cleanup VM operation. Also the
>> delay_to_keep_mmu mostly only does a series of sleep() calls which do
>> not count towards that thread's vtime.
>>
>> In my tests, this time additionally added (obviously) does not
>> correspond to cleanup time at all.
>>
>>> 2. Remove '_init_mark' which is not used.
>> I think this is supposed to track initial mark STW pauses - maybe at
>> some point they were not piggy-backed onto a regular evacuation pause.
>>
>>> This CR also mentioned about 2 more items but #3 is resulted from
>>> misunderstanding of the log and #4 is already fixed.
>>>
>>> CR: https://bugs.openjdk.java.net/browse/JDK-8068344
>>> Webrev: http://cr.openjdk.java.net/~sangheki/8068344/webrev.00
>>> Testing: JPRT, local test to measure the time report
>> As an RFE for this change, it would be great to overhaul the time
>> tracking of the concurrent threads by moving all timing into a separate
>> class (e.g. "like" G1GCPhaseTimes), and use scoped objects to track the
>> times.
>>
>> Then track and print all phases of the various mark stw pauses.
>>
>> Imo this change looks like random fixing of something broken into
>> something similarly broken to me.
>>
>> Thanks,
>>    Thomas
>>
>