<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
</head>
<body text="#000000" bgcolor="#FFFFFF">
Hi all,<br>
<br>
I had some discussions with Thomas and updated webrev with below
items.<br>
<br>
0. Agreed to use webrev.3b.<br>
1. Moved ReferenceProcessorPhaseTimes from G1CollectedHeap to
G1PhaseTimes.<br>
- Changed to stack allocate ReferenceProcessPhaseTimes in
G1PhaseTimes.<br>
- ReferenceProcessorPhaseTimes is created from constructor of
G1PhaseTimes.<br>
2. Simplified the condition at
G1GCPhaseTimes::debug_time_for_reference.<br>
3. Removed ReferenceProcessorPhaseTimes::processing_is_mt() method.<br>
4. Removed bool processing_is_mt from constructor of
ReferenceProcessorPhaseTimes class.<br>
5. Re-based code to latest source code.<br>
6. Updated to use new log classes.<br>
7. Some clean-ups in ReferenceProcessorPhaseTimes.<br>
<br>
Webrev:<br>
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~sangheki/8173335/webrev.4">http://cr.openjdk.java.net/~sangheki/8173335/webrev.4</a> (full)<br>
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~sangheki/8173335/webrev.4_to_3b">http://cr.openjdk.java.net/~sangheki/8173335/webrev.4_to_3b</a> (inc)<br>
<br>
Testing: JPRT<br>
<br>
Thanks,<br>
Sangheon<br>
<br>
<br>
<div class="moz-cite-prefix">On 06/29/2017 12:56 AM, sangheon wrote:<br>
</div>
<blockquote type="cite"
cite="mid:d334abc5-16f5-83ac-8336-b871a36b78cb@oracle.com">
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
Hi Thomas,<br>
<br>
Thank you very much for the thorough review.<br>
<br>
<div class="moz-cite-prefix">On 06/26/2017 07:42 AM, Thomas
Schatzl wrote:<br>
</div>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">Hi Sangheon,
thanks for all your changes, and sorry a bit for the delay...
On Wed, 2017-06-14 at 00:52 -0700, sangheon wrote:
</pre>
<blockquote type="cite">
<pre wrap="">Hi Thomas again,
On 06/13/2017 02:21 PM, sangheon wrote:
</pre>
<blockquote type="cite">
<pre wrap="">Hi Thomas,
Thank you for reviewing this.
On 06/13/2017 04:21 AM, Thomas Schatzl wrote:
</pre>
<blockquote type="cite">
<pre wrap="">Hi Sangheon,
On Mon, 2017-06-12 at 17:13 -0700, sangheon wrote:
</pre>
<blockquote type="cite">
<pre wrap="">Hi Aleksey,
Thanks for the review.
On 06/12/2017 09:06 AM, Aleksey Shipilev wrote:
</pre>
<blockquote type="cite">
<pre wrap="">On 06/10/2017 01:57 AM, sangheon wrote:
</pre>
<blockquote type="cite">
<pre wrap="">CR: <a class="moz-txt-link-freetext" href="https://bugs.openjdk.java.net/browse/JDK-8173335" moz-do-not-send="true">https://bugs.openjdk.java.net/browse/JDK-8173335</a>
webrev: <a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/%7Esangheki/8173335/webrev" moz-do-not-send="true">http://cr.openjdk.java.net/~sangheki/8173335/webrev</a>
.0
</pre>
</blockquote>
</blockquote>
</blockquote>
<pre wrap="">- There should be a destructor in ReferenceProcessor cleaning up
the dynamically allocated memory.
</pre>
</blockquote>
<pre wrap="">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(
<a class="moz-txt-link-freetext" href="https://bugs.openjdk.java.net/browse/JDK-8182120" moz-do-not-send="true">https://bugs.openjdk.java.net/browse/JDK-8182120</a> ) 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.
</pre>
</blockquote>
</blockquote>
<pre wrap="">That's fine, thanks.
</pre>
<blockquote type="cite">
<blockquote type="cite">
<blockquote type="cite">
<pre wrap="">- 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.
</pre>
</blockquote>
<pre wrap="">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?!
</pre>
</blockquote>
</blockquote>
<pre wrap="">Yes. In the example you showed me earlier with gc+ref=trace the
examples did not contain the other gc+ref=trace output. That's why I
thought it would be fine. :)</pre>
</blockquote>
:)<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<blockquote type="cite">
<blockquote type="cite">
<blockquote type="cite">
<pre wrap="">- 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?
</pre>
</blockquote>
<pre wrap="">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.
</pre>
<blockquote type="cite">
<pre wrap="">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.
</pre>
</blockquote>
<pre wrap="">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)
</pre>
</blockquote>
<pre wrap="">I started working on above 2 items. :)
I will update webrev when I'm ready.
</pre>
</blockquote>
<pre wrap="">Thanks a lot for considering all my comments.
I think the output is much nicer now :)</pre>
</blockquote>
Thanks!<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">Some more notes:
- In the current change (webrev.2) the method with using the
"direct_print()" getter seems a bit forced only to keep the current
structure of the code, i.e. printing within the
ReferenceProcessor::process_references() method.</pre>
</blockquote>
Right.<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">What do you think about moving the printing outside of that method for
all collectors, just passing a (properly initialized - that allows
moving the reset() method into gc specific code as well)
ReferenceProcessorPhaseTimes* that is then later used for printing,
either directly, or deferred?</pre>
</blockquote>
Okay, this seems better than current one.<br>
During applying your suggestion, I tweaked a little bit, because
giving the responsibility of printing logs to the callers seems
not that natural to me. (I also prepared additional webrev for
your original suggestion [1])<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">At the location where the reference processing is done we know whether
we need to print directly or deferred. This also hides pretty specific
information about printing (like indentation level) from the reference
processing itself.
Also that would maybe allow storing the GCTimer reference somewhere in
the ReferenceProcessorPhaseTimes so that we only need to pass a single
container for timing information around.</pre>
</blockquote>
Good idea, now GCTimer is included in
ReferenceProcessorPhaseTimes. <br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">Overall that may reduce the code quite a bit, keeps similar components
(GCTimer and ReferenceProcessorPhaseTimes) together without
ReferenceProcessor needing to know about both of them, and removes the
ReferenceProcessor "global" reference to the
ReferenceProcessorPhaseTimes, which is easier to keep track of when
looking at the code (instead of having the GCTimer passed in and the
ReferenceProcessorPhaseTimes as member).
The collectors that print immediately probably also can get away with a
stack-allocated local ReferenceProcessorPhaseTimes, which somewhat
simplifies their lifecycle management.</pre>
</blockquote>
Right.<br>
<br>
Mostly ReferenceProcessorPhaseTimes will be stack-allocated at the
time of calling process_discovered_references() or
enqueue_discovered_references(), except for G1 young GC case.<br>
<br>
~ReferenceProcessorPhaseTimes() will not be added in the
destructor of G1CollectedHeap as we don't have it now. This can be
addressed in separate CR if needed.<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">- could you please tighten the visibility of
ReferenceProcessorPhaseTimes methods a bit? The getters of that class
are only ever used in the print* methods, and even some of these print*
methods are ever called from class local methods.
I think this would drastically decrease the surface of that method.</pre>
</blockquote>
You are right.<br>
Tried to move to 'private' as many as possible.<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">- there seems to be a bug in printing per-thread per-phase worker
times, the values seem to contain the absolute time at which the list
has been processed, not a duration. (with -XX:+ParallelRefProcEnabled
and gc+phases+ref=trace)
[1512.286s][debug][gc,phases,ref] GC(834) Reference Processing: 2.5ms
[1512.286s][debug][gc,phases,ref] GC(834) SoftReference: 0.3ms
[1512.286s][debug][gc,phases,ref] GC(834) Balance queues: 0.0ms
[1512.286s][debug][gc,phases,ref] GC(834) Phase1: 0.3ms
[1512.286s][trace][gc,phases,ref] GC(834) Process lists
(ms) Min: 1512283.9, Avg: 1512283.9, Max: 1512283.9, Diff: 0.0,
Sum: 34782529.1, Workers: 23
[1512.286s][debug][gc,phases,ref] GC(834) Phase2: 0.3ms
[1512.286s][trace][gc,phases,ref] GC(834) Process lists
(ms) Min: 1512284.2, Avg: 1512284.2, Max: 1512284.2, Diff: 0.0,
Sum: 34782535.9, Workers: 23
- in referenceProcessorPhaseTimes.cpp:35: the code reads
if (_worker_time != NULL) {
...
}
with _worker_time being set to NULL just one line above (same with the
other constructor).
Not sure.</pre>
</blockquote>
_worker_time check was remainder of previous change and resulted
in above bug you pointed.<br>
Thanks for catching this.<br>
Fixed.<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">- in RefProcWorkerTimeTracker::~RefProcWorkerTimeTracker: how is it
possible that _worker_time is NULL? ReferenceProcessorPhaseTimes seems
to always allocate memory for it.</pre>
</blockquote>
Fixed.<br>
_worker_time can't be NULL.<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">- RefProcPhaseTimesTracker takes the DiscoveredList array as parameter,
but only ever uses it to determine how many total entries this
DiscoveredList[] has. So it seems to me that it would be better in the
name of information hiding if the ReferenceProcessor, which already has
a total_count() method, would just pass this total instead of the
entire list.</pre>
</blockquote>
The problem is that 'before/after' count should be gathered from
constructor and destructor.<br>
With passing a parameter, constructor could get the total but it
is impossible from destructor.<br>
<br>
But I agree with your point that passing DiscoveredList to get the
total-count can be enhanced. So I changed to add a new method that
returns total count at ReferenceProcessor(per ReferenceType). With
this new approach, we can simplify a bit more. e.g. eliminate
ReferenceProcessorPhaseTimes::max_gc_threads() and
total_count_from_list() etc.<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">This would also remove the need for the max_gc_counts() getter in
ReferenceProcessorPhaseTimes afaics too.</pre>
</blockquote>
[...]<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">- "Ref Counts" vs. "Reference Counts" vs. something else in the output
of the enqueue phase: I would prefer to not use abbreviations. Since we
already mess up the logging output in a big way, we might also just go
all the way :P</pre>
</blockquote>
Changed to use 'Reference Counts'.<br>
<br>
Updated webrev:<br>
<a class="moz-txt-link-freetext"
href="http://cr.openjdk.java.net/%7Esangheki/8173335/webrev.3"
moz-do-not-send="true">http://cr.openjdk.java.net/~sangheki/8173335/webrev.3</a><br>
<a class="moz-txt-link-freetext"
href="http://cr.openjdk.java.net/%7Esangheki/8173335/webrev.3_to_2/"
moz-do-not-send="true">http://cr.openjdk.java.net/~sangheki/8173335/webrev.3_to_2/</a><br>
<br>
Testing: JPRT and local test with all collectors.<br>
<br>
[1]: with your suggestion, callers will stack allocate
ReferenceProcessorPhaseTimes and GCTimer can be included in
ReferenceProcessorPhaseTimes. i.e. applied only your suggestion<br>
<a class="moz-txt-link-freetext"
href="http://cr.openjdk.java.net/%7Esangheki/8173335/webrev.3b"
moz-do-not-send="true">http://cr.openjdk.java.net/~sangheki/8173335/webrev.3b</a><br>
<a class="moz-txt-link-freetext"
href="http://cr.openjdk.java.net/%7Esangheki/8173335/webrev.3b_to_2/"
moz-do-not-send="true">http://cr.openjdk.java.net/~sangheki/8173335/webrev.3b_to_2/</a><br>
<br>
Thanks,<br>
Sangheon<br>
<br>
<br>
<blockquote type="cite"
cite="mid:1498488133.2665.37.camel@oracle.com">
<pre wrap="">Thanks,
Thomas
</pre>
</blockquote>
<br>
</blockquote>
<br>
</body>
</html>