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

[Thomas Schatzl]

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