<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
</head>
<body text="#000000" bgcolor="#FFFFFF">
Hi Thomas,<br>
<br>
<div class="moz-cite-prefix">On 06/14/2017 12:52 AM, sangheon wrote:<br>
</div>
<blockquote type="cite"
cite="mid:0353babf-03eb-21cd-b286-9b0149dfb718@oracle.com">Hi
Thomas again,
<br>
<br>
On 06/13/2017 02:21 PM, sangheon wrote:
<br>
<blockquote type="cite">Hi Thomas,
<br>
<br>
Thank you for reviewing this.
<br>
<br>
On 06/13/2017 04:21 AM, Thomas Schatzl wrote:
<br>
<blockquote type="cite">Hi Sangheon,
<br>
<br>
<br>
On Mon, 2017-06-12 at 17:13 -0700, sangheon wrote:
<br>
<blockquote type="cite">Hi Aleksey,
<br>
<br>
Thanks for the review.
<br>
<br>
On 06/12/2017 09:06 AM, Aleksey Shipilev wrote:
<br>
<blockquote type="cite">On 06/10/2017 01:57 AM, sangheon
wrote:
<br>
<blockquote type="cite">CR:
<a class="moz-txt-link-freetext" href="https://bugs.openjdk.java.net/browse/JDK-8173335">https://bugs.openjdk.java.net/browse/JDK-8173335</a>
<br>
webrev:
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~sangheki/8173335/webrev.0">http://cr.openjdk.java.net/~sangheki/8173335/webrev.0</a>
<br>
</blockquote>
</blockquote>
</blockquote>
- There should be a destructor in ReferenceProcessor cleaning
up the
<br>
dynamically allocated memory.
<br>
</blockquote>
Thomas and I had some discussion about this and agreed to file a
separate CR for freeing issue.
<br>
<br>
I noticed that there's no destructor when I wrote this, but this
is how we usually implement.
<br>
However as this seems incorrect, I will add a destructor for
newly added class but it will not be used in this patch.
<br>
It will be used in the following CR(
<a class="moz-txt-link-freetext" href="https://bugs.openjdk.java.net/browse/JDK-8182120">https://bugs.openjdk.java.net/browse/JDK-8182120</a> ) which fixes
not-freeing issue in ReferenceProcessor.
<br>
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.
<br>
<br>
<blockquote type="cite">
<br>
- the change should move gc+ref output to something else:
there is so
<br>
much additional junk printed with gc+ref=trace so that the
phase
<br>
logging is drowned out with real trace information and
unusable for
<br>
regular consumption.
<br>
</blockquote>
Okay, I will add it.
<br>
But I asked introducing 'gc+ref+phases' before but you didn't
like it. :) Probably I didn't provide much details?!
<br>
<br>
<blockquote type="cite">
<br>
Also I would prefer to have this detailed log output
interspersed
<br>
within the (existing) gc+phases output. Like under the
"Reference
<br>
Processing" and "Reference Enqueuing" sections for G1 in
particular.
<br>
</blockquote>
Frankly speaking, I'm not much interested now.
<br>
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. :) )
<br>
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.
<br>
Ref. logs are printed separately for long time and other shared
codes also print logs immediately.
<br>
<br>
On the other hand, current implementation(re-use and print
immediately) seems simpler to implement.
<br>
In addition, ReferenceProcessor::process_discovered_reflist() is
repeatedly called for different type of References so re-using
log printer seems natural to me. :)
<br>
<br>
<blockquote type="cite">
<br>
Maybe with gc+phases+ref=debug/trace so that "everything"
could be
<br>
enabled using "gc+phases*=debug/trace"?
<br>
</blockquote>
Yes, good idea.
<br>
<br>
<blockquote type="cite">
<br>
I can see that the code throws away the previous information
about
<br>
reference processing after every use (the phasetimes reused).
This is
<br>
does not allow printing of the data at convenient times and
places.
<br>
<br>
I.e. I would prefer if the data were aggregated (not only from
one
<br>
particular phase) and later printed together.
<br>
</blockquote>
If we don't intersperse with existing G1 log, do you still think
printing later is needed?
<br>
Probably printing after Phanthom Ref. processed or different
location?
<br>
<br>
<blockquote type="cite">
<br>
I kind of disagree with Aleksey about need for backwards
compatibility
<br>
of log messages. This is such a big breaking change in the
amount of
<br>
information shown that existing users will want to adapt their
log
<br>
readers anyway.
<br>
</blockquote>
True that log parsers already should be updated, but I
understood Aleksey's comment something like preferring 'Ref
Counts' instead of 'Counts'.
<br>
<br>
<blockquote type="cite">As mentioned, due to real trace code
here, gc+ref=trace is unusable.
<br>
</blockquote>
FYI, probably you tested with fastdebug because there are many
debug/trace logs for debug build. It doesn't bother from product
build actually.
<br>
But as I said, I will change current new logs' channel from
'gc+ref' to 'gc+phases+ref'.
<br>
<br>
<blockquote type="cite">
<br>
We could still provide minimal backwards compatible output
under
<br>
gc+ref=debug if needed.
<br>
</blockquote>
I'm don't see much value on this.
<br>
gc+phases+ref seems better.
<br>
<br>
<blockquote type="cite">
<br>
- I would prefer if resetting the reference phase times logger
wouldn't
<br>
be kind of an afterthought of printing :)
<br>
<br>
Also it might be useful to keep the data around for somewhat
longer
<br>
(not throw it away after every phase). Don't we need the data
for
<br>
further analysis?
<br>
</blockquote>
I don't have strong opinion on this.
<br>
<br>
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.
<br>
<br>
<blockquote type="cite">
<br>
This would also allow printing it later using different log
tags (with
<br>
different formatting).
<br>
<br>
- I like the split of phasetimes into data storage and
printing. I do
<br>
not like that basically the timing data is created twice, once
for the
<br>
phasetimes, once for the GCTimer (for JFR basically).
<br>
</blockquote>
No, currently timing data is created once and used for both
phase log and GCTimer.
<br>
Or am I missing something?
<br>
<br>
So in summary, mostly I agree with your comments except below 2:
<br>
1. Interspersing with G1 log.
<br>
2. Keeping log data longer. (This should be done if we go with
interspersing idea)
<br>
</blockquote>
I started working on above 2 items. :)
<br>
I will update webrev when I'm ready.
<br>
</blockquote>
Here's updated webrevs which applied below:<br>
<br>
1. Added destructor for ReferenceProcessorPhaseTimes.<br>
2. Added 'gc+phases+ref' for newly added logs.<br>
3. Interspersing reference logs into G1 young GC log.<br>
- Logs for other cases will be printed immediately.<br>
4. All timing information have their own storage.<br>
5. Total time is added.<br>
<br>
Current reference logs will be:<br>
1. New logs (except G1 young GC)<br>
<tt>[1.541s][debug][gc,phases ] GC(7) Finalize Marking 4.802ms</tt><tt><br>
</tt><tt>[1.541s][debug][gc,phases,start] GC(7) <b><u>Reference
Processing</u></b></tt><tt><b><u> <-- [1]</u></b><br>
</tt><b><tt>[1.543s][debug][gc,phases,ref ] GC(7) Reference
Processing: 1.8ms</tt></b><b><tt> <-- [2]<br>
</tt></b><b><tt>[1.543s][debug][gc,phases,ref ] GC(7)
SoftReference: 0.3ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][debug][gc,phases,ref ] GC(7) Balance
queues: 0.0ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][debug][gc,phases,ref ] GC(7) Phase1:
0.3ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][trace][gc,phases,ref ] GC(7)
Process lists (ms) Min: 1541.3, Avg: 1541.3, Max: 1541.3,
Diff: 0.0, Sum: 35450.0, Workers: 23</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][debug][gc,phases,ref ] GC(7) Phase2:
0.2ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][trace][gc,phases,ref ] GC(7)
Process lists (ms) Min: 1541.5, Avg: 1541.5, Max: 1541.5,
Diff: 0.0, Sum: 35454.5, Workers: 23</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][debug][gc,phases,ref ] GC(7) Phase3:
0.3ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][trace][gc,phases,ref ] GC(7)
Process lists (ms) Min: 1541.7, Avg: 1541.8, Max: 1541.8,
Diff: 0.0, Sum: 35460.5, Workers: 23</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][debug][gc,phases,ref ] GC(7)
Discovered: 0</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][debug][gc,phases,ref ] GC(7)
Cleared: 0</tt></b><b><tt><br>
</tt></b><b><tt>...</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][debug][gc,phases,ref ] GC(7) Reference
Enqueuing 0.1ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][trace][gc,phases,ref ] GC(7) Process
lists (ms) Min: 1543.4, Avg: 1543.4, Max: 1543.4, Diff:
0.1, Sum: 35498.4, Workers: 23</tt></b><b><tt><br>
</tt></b><b><tt>[1.543s][debug][gc,phases,ref ] GC(7) Ref
Counts: Soft: 0 Weak: 0 Final: 0 Phantom: 0</tt></b><tt><br>
</tt><tt>[1.544s][debug][gc,phases ] GC(7) Reference Processing
2.445ms</tt><tt><br>
</tt><tt>[1.544s][debug][gc,phases,start] GC(7) Class Unloading</tt><tt><br>
</tt><tt>[1.544s][debug][gc,phases,start] GC(7) ClassLoaderData</tt><tt><br>
</tt><tt>[1.544s][debug][gc,phases ] GC(7) ClassLoaderData
0.467ms</tt><br>
<br>
2. New logs for G1 young GC: -Xlog:gc+phases*=trace<br>
<tt>[1.470s][info ][gc,phases ] GC(6) Post Evacuate Collection
Set: 4.1ms</tt><tt><br>
</tt><tt>[1.470s][debug][gc,phases ] GC(6) Code Roots Fixup:
0.0ms</tt><tt><br>
</tt><tt>[1.470s][debug][gc,phases ] GC(6) Preserve CM Refs:
0.0ms</tt><tt><br>
</tt><tt>[1.470s][trace][gc,phases ] GC(6) Parallel
Preserve CM Refs (ms): skipped</tt><tt><br>
</tt><tt>[1.470s][trace][gc,phases,task]
GC(6) - - - - - - - - - - - - - -
- - - - - - - - -</tt><tt><br>
</tt><b><tt>[1.470s][debug]<u>[gc,phases ]</u> GC(6)
Reference Processing: 1.4ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][debug][gc,phases,ref ] GC(6)
SoftReference: 0.2ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][debug][gc,phases,ref ] GC(6)
Balance queues: 0.0ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][debug][gc,phases,ref ] GC(6)
Phase1: 0.2ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][trace][gc,phases,ref ] GC(6)
Process lists (ms) Min: 1463.2, Avg: 1463.2, Max: 1463.2,
Diff: 0.0, Sum: 33653.2, Workers: 23</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][debug][gc,phases,ref ] GC(6)
Phase2: 0.1ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][trace][gc,phases,ref ] GC(6)
Process lists (ms) Min: 1463.3, Avg: 1463.3, Max: 1463.4,
Diff: 0.0, Sum: 33656.8, Workers: 23</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][debug][gc,phases,ref ] GC(6)
Phase3: 0.2ms</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][trace][gc,phases,ref ] GC(6)
Process lists (ms) Min: 1463.5, Avg: 1463.5, Max: 1463.6,
Diff: 0.0, Sum: 33661.6, Workers: 23</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][debug][gc,phases,ref ] GC(6)
Discovered: 0</tt></b><b><tt><br>
</tt></b><b><tt>[1.470s][debug][gc,phases,ref ] GC(6)
Cleared: 0</tt></b><tt><br>
</tt><tt>...</tt><tt><br>
</tt><tt>[1.471s][debug][gc,phases ] GC(6) Clear Card Table:
0.0ms</tt><tt><br>
</tt><tt><b>[1.471s][debug][gc,phases ] GC(6) Reference
Enqueuing: 0.1ms</b></tt><tt><b><br>
</b></tt><tt><b>[1.471s][debug][gc,phases,ref ] GC(6) Ref
Counts: Soft: 0 Weak: 0 Final: 0 Phantom: 0</b></tt><tt><br>
</tt><tt>[1.471s][debug][gc,phases ] GC(6) Merge Per-Thread
State: 0.2ms</tt><br>
<br>
3. New logs for G1 young GC: -Xlog:gc+phases+ref=trace<br>
<tt>[1.335s][debug]<u><b>[gc,phases,ref]</b></u> GC(4) Reference
Processing: 9.4ms</tt><tt> <u><b><- This is still printed.</b></u><br>
</tt><tt>[1.335s][debug][gc,phases,ref] GC(4) SoftReference:
7.0ms</tt><tt><br>
</tt><tt>[1.335s][debug][gc,phases,ref] GC(4) Balance
queues: 0.0ms</tt><tt><br>
</tt><tt>[1.335s][debug][gc,phases,ref] GC(4) Phase1: 7.0ms</tt><tt><br>
</tt><tt>[1.335s][trace][gc,phases,ref] GC(4) Process
lists (ms) Min: 1329.0, Avg: 1329.0, Max: 1329.1, Diff:
0.1, Sum: 30568.1, Workers: 23</tt><tt><br>
</tt><tt>[1.335s][debug][gc,phases,ref] GC(4) Phase2: 0.1ms</tt><tt><br>
</tt><tt>[1.335s][trace][gc,phases,ref] GC(4) Process
lists (ms) Min: 1329.1, Avg: 1329.1, Max: 1329.1, Diff:
0.0, Sum: 30569.7, Workers: 23</tt><tt><br>
</tt><tt>[1.335s][debug][gc,phases,ref] GC(4) Phase3: 0.3ms</tt><tt><br>
</tt><tt>[1.335s][trace][gc,phases,ref] GC(4) Process
lists (ms) Min: 1329.4, Avg: 1329.4, Max: 1329.5, Diff:
0.1, Sum: 30576.7, Workers: 23</tt><tt><br>
</tt><tt>[1.335s][debug][gc,phases,ref] GC(4) Discovered: 0</tt><tt><br>
</tt><tt>[1.335s][debug][gc,phases,ref] GC(4) Cleared: 0</tt><tt><br>
</tt>...<br>
<tt></tt><tt>[1.335s][debug][gc,phases,ref] GC(4) Reference
Enqueuing: 0.1ms</tt><tt><br>
</tt><tt>[1.335s][debug][gc,phases,ref] GC(4) Ref Counts:
Soft: 0 Weak: 0 Final: 0 Phantom: 0</tt><br>
<br>
[1]: Among implementations 'Reference Processing' GCTraceTime are
measuring differently. Some include
ReferenceProcessor::enqueue_discovered_references() while others
don't. i.e. The former is something like measuring all reference
process related work rather than process_discovered_references(). As
to have its own total time seems right to me, I added it[2]. <br>
<br>
PS) There were some concern about exposing WorkerDataArray into
'shared' directory. But as there's no alternative to use, I'm hoping
to share it now.<br>
<br>
Webrev:<br>
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~sangheki/8173335/webrev.2">http://cr.openjdk.java.net/~sangheki/8173335/webrev.2</a> (full)<br>
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~sangheki/8173335/webrev.2_to_1/">http://cr.openjdk.java.net/~sangheki/8173335/webrev.2_to_1/</a>
(incremental)<br>
<br>
Thanks,<br>
Sangheon<br>
<br>
<br>
<br>
<blockquote type="cite"
cite="mid:0353babf-03eb-21cd-b286-9b0149dfb718@oracle.com">
<br>
Thanks,
<br>
Sangheon
<br>
<br>
<br>
<blockquote type="cite">
<br>
Let me post updated webrev, after making all decision.
<br>
<br>
Thanks,
<br>
Sangheon
<br>
<br>
<br>
<blockquote type="cite">Or the gctimer is
<br>
passed everywhere. But that is another issue I guess.
<br>
<br>
Thanks,
<br>
Thomas
<br>
<br>
<br>
<blockquote type="cite">
<blockquote type="cite">Oh, good! I had to instrument these
by hand when optimizing RP
<br>
paths.
<br>
<br>
Comments after brief look:
<br>
<br>
*) So, the path with NULL executor are also not
handling the
<br>
timer? E.g. CMS:
<br>
<br>
5262 if (rp->processing_is_mt()) {
<br>
5263 rp->balance_all_queues();
<br>
5264 CMSRefProcTaskExecutor task_executor(*this);
<br>
5265
rp->enqueue_discovered_references(&task_executor,
<br>
_gc_timer_cm);
<br>
5266 } else {
<br>
5267 rp->enqueue_discovered_references(NULL);
<br>
5268 }
<br>
</blockquote>
Fixed to use timers for similar cases that you pointed.
Thanks for
<br>
catching up this!
<br>
I started this CR as a part of MT ref.
processing(JDK-8043575), so I
<br>
only added to that path. But this should be fixed.
<br>
<blockquote type="cite">
<br>
*) I would leave "Ref Counts" line as usual for
compatibility
<br>
reasons. Changing
<br>
it to "Counts" would force GC log parsers to handle that
corner
<br>
case too.
<br>
</blockquote>
Changed, 'Counts -> Ref Counts'.
<br>
<blockquote type="cite">
<br>
*) This may reuse Indents?
<br>
<br>
95 out->print("%s", " ");
<br>
</blockquote>
Fixed to use Indents[2].
<br>
<br>
<blockquote type="cite">
<br>
*) Probably makes sense to "hg mv -A" the
workerDataArray files
<br>
to preserve the
<br>
Mercurial history -- webrev should say something like
"copied from
<br>
...", IIRC.
<br>
</blockquote>
Fixed.
<br>
<br>
webrev:
<br>
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~sangheki/8173335/webrev.1/">http://cr.openjdk.java.net/~sangheki/8173335/webrev.1/</a>
<br>
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~sangheki/8173335/webrev.1_to_0">http://cr.openjdk.java.net/~sangheki/8173335/webrev.1_to_0</a>
<br>
<br>
Thanks,
<br>
Sangheon
<br>
<br>
<br>
<blockquote type="cite">
<br>
Thanks,
<br>
-Aleksey
<br>
<br>
</blockquote>
</blockquote>
</blockquote>
<br>
</blockquote>
<br>
</blockquote>
<br>
</body>
</html>