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

Tue Jun 13 21:21:29 UTC 2017

Hi Thomas,

Thank you for reviewing this.

On 06/13/2017 04:21 AM, Thomas Schatzl wrote:
> 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.
Thomas and I had some discussion about this and agreed to file a 
separate CR for freeing issue.

I noticed that there's no destructor when I wrote this, but this is how 
we usually implement.
However as this seems incorrect, I will add a destructor for newly added 
class but it will not be used in this patch.
It will be used in the following CR( 
https://bugs.openjdk.java.net/browse/JDK-8182120 ) which fixes 
not-freeing issue in ReferenceProcessor.
FYI, ReferenceProcessor has heap allocated members of 
ReferencePolicy(and its friends) but it is not freed too. So instead of 
extending this patch, I propose to separate this freeing issue.

>
> - 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.
Okay, I will add it.
But I asked introducing 'gc+ref+phases' before but you didn't like it. 
:) Probably I didn't provide much details?!

>
> 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.
Frankly speaking, I'm not much interested now.
When I started investigating this CR, you mentioned about this too. (But 
you were okay for either way. i.e. current one or interspersing into G1 
logging. :) )
I also tried in that way(interspersing one) and my feeling is that I 
don't see much benefit to have ref logs in G1 phases section. It looks 
better organized but it doesn't mean current log style is worse.
Ref. logs are printed separately for long time and other shared codes 
also print logs immediately.

On the other hand, current implementation(re-use and print immediately) 
seems simpler to implement.
In addition, ReferenceProcessor::process_discovered_reflist() is 
repeatedly called for different type of References so re-using log 
printer seems natural to me. :)

>
> Maybe with gc+phases+ref=debug/trace so that "everything" could be
> enabled using "gc+phases*=debug/trace"?
Yes, good idea.

>
> 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.
If we don't intersperse with existing G1 log, do you still think 
printing later is needed?
Probably printing after Phanthom Ref. processed or different location?

>
> 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.
True that log parsers already should be updated, but I understood 
Aleksey's comment something like preferring 'Ref Counts' instead of 
'Counts'.

> As mentioned, due to real trace code here, gc+ref=trace is unusable.
FYI, probably you tested with fastdebug because there are many 
debug/trace logs for debug build. It doesn't bother from product build 
actually.
But as I said, I will change current new logs' channel from 'gc+ref' to 
'gc+phases+ref'.

>
> We could still provide minimal backwards compatible output under
> gc+ref=debug if needed.
I'm don't see much value on this.
gc+phases+ref seems better.

>
> - 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?
I don't have strong opinion on this.

I didn't consider keeping log data for further analysis. This could a 
minor reason for supporting keeping log data longer but I think 
interspersing with existing G1 log would be the main reason of keeping it.

>
> 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).
No, currently timing data is created once and used for both phase log 
and GCTimer.
Or am I missing something?

So in summary, mostly I agree with your comments except below 2:
1. Interspersing with G1 log.
2. Keeping log data longer. (This should be done if we go with 
interspersing idea)

Let me post updated webrev, after making all decision.

Thanks,
Sangheon

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