RFR(S): 8173335: Improve logging for j.l.ref.reference processing

Thomas Schatzl thomas.schatzl at oracle.com
Tue Jun 13 11:21:22 UTC 2017


Hi Sangheon,


On Mon, 2017-06-12 at 17:13 -0700, sangheon wrote:
> Hi Aleksey,
> 
> Thanks for the review.
> 
> On 06/12/2017 09:06 AM, Aleksey Shipilev wrote:
> > 
> > On 06/10/2017 01:57 AM, sangheon wrote:
> > > 
> > > CR: https://bugs.openjdk.java.net/browse/JDK-8173335
> > > webrev: http://cr.openjdk.java.net/~sangheki/8173335/webrev.0

- There should be a destructor in ReferenceProcessor cleaning up the
dynamically allocated memory.

- the change should move gc+ref output to something else: there is so
much additional junk printed with gc+ref=trace so that the phase
logging is drowned out with real trace information and unusable for
regular consumption.

Also I would prefer to have this detailed log output interspersed
within the (existing) gc+phases output. Like under the "Reference
Processing" and "Reference Enqueuing" sections for G1 in particular.

Maybe with gc+phases+ref=debug/trace so that "everything" could be
enabled using "gc+phases*=debug/trace"?

I can see that the code throws away the previous information about
reference processing after every use (the phasetimes reused). This is
does not allow printing of the data at convenient times and places.

I.e. I would prefer if the data were aggregated (not only from one
particular phase) and later printed together.

I kind of disagree with Aleksey about need for backwards compatibility
of log messages. This is such a big breaking change in the amount of
information shown that existing users will want to adapt their log
readers anyway.
As mentioned, due to real trace code here, gc+ref=trace is unusable.

We could still provide minimal backwards compatible output under
gc+ref=debug if needed.

- I would prefer if resetting the reference phase times logger wouldn't
be kind of an afterthought of printing :)

Also it might be useful to keep the data around for somewhat longer
(not throw it away after every phase). Don't we need the data for
further analysis?

This would also allow printing it later using different log tags (with
different formatting).

- I like the split of phasetimes into data storage and printing. I do
not like that basically the timing data is created twice, once for the
phasetimes, once for the GCTimer (for JFR basically). Or the gctimer is
passed everywhere. But that is another issue I guess.

Thanks,
  Thomas


> > Oh, good! I had to instrument these by hand when optimizing RP
> > paths.
> > 
> > Comments after brief look:
> > 
> >   *) So, the path with NULL executor are also not handling the
> > timer? E.g. CMS:
> > 
> >   5262   if (rp->processing_is_mt()) {
> >   5263     rp->balance_all_queues();
> >   5264     CMSRefProcTaskExecutor task_executor(*this);
> >   5265     rp->enqueue_discovered_references(&task_executor,
> > _gc_timer_cm);
> >   5266   } else {
> >   5267     rp->enqueue_discovered_references(NULL);
> >   5268   }
> Fixed to use timers for similar cases that you pointed. Thanks for 
> catching up this!
> I started this CR as a part of MT ref. processing(JDK-8043575), so I 
> only added to that path. But this should be fixed.
> > 
> > 
> >   *) I would leave "Ref Counts" line as usual for compatibility
> > reasons. Changing
> > it to "Counts" would force GC log parsers to handle that corner
> > case too.
> Changed, 'Counts -> Ref Counts'.
> > 
> > 
> >   *) This may reuse Indents?
> > 
> >     95       out->print("%s", "    ");
> Fixed to use Indents[2].
> 
> > 
> > 
> >   *) Probably makes sense to "hg mv -A" the workerDataArray files
> > to preserve the
> > Mercurial history -- webrev should say something like "copied from
> > ...", IIRC.
> Fixed.
> 
> webrev:
> http://cr.openjdk.java.net/~sangheki/8173335/webrev.1/
> http://cr.openjdk.java.net/~sangheki/8173335/webrev.1_to_0
> 
> Thanks,
> Sangheon
> 
> 
> > 
> > 
> > Thanks,
> > -Aleksey
> > 



More information about the hotspot-gc-dev mailing list