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

[sangheon]

Hi Thomas,

Okay, I filed a new CR to address this.
https://bugs.openjdk.java.net/browse/JDK-8153770
And as you suggested this new class will be separated from STW stuff.

Thanks,
Sangheon


On 04/07/2016 07:56 AM, Thomas Schatzl wrote:
> Hi Sangheon,
>
> On Thu, 2016-04-07 at 07:36 -0700, sangheon wrote:
>> Hi Thomas,
>>
>> Thanks for reviewing this.
>>
>> On 04/07/2016 03:18 AM, 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.
>> Agree.
>> I think just moving measurement of vtime to at the end of cycle will
>> be fine.
>> Move below 2 calls after the cm()->concurrent_cycle_end().
>> double end_time = os::elapsedVTime();
>> _vtime_accum = (end_time - _vtime_start);
> As mentioned, _vtime_accum = os::elapsedVTime(); should be sufficient.
> Os::elapsedVTime() already returns the accumulated cpu time for this
> thread.
>
> Since the code is that bad, I would prefer not spending more time on
> this, and just close this as "Won't fix" as Bengt suggested. I mean,
> the change won't give you much more accurate readings anyway.
>
> I think the main issues were point 3+4 in the bug report, which have
> already been fixed elsewhere.
>
>>>> 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.
>> Agree.
>> I was also thinking that(including concurrent time report into
>> G1GCPhaseTimes) as well.I will file a new one.
> I would kind of prefer if concurrent mark phases/pause time timings
> were separate from the young gc stw pause timings.
>
> Some of the infrastructure could be reused of course.
>
> Thanks,
>    Thomas
>