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

[sangheon]

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

>
>> 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.
Yes.
I just removed it as we are not using it now.

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

Thanks,
Sangheon


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