<html>
<head>
<meta content="text/html; charset=utf-8" http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hi Bengt,<br>
<br>
Thank you for looking at this change.<br>
<br>
<div class="moz-cite-prefix">On 09/30/2014 01:36 AM, Bengt Rutisson
wrote:<br>
</div>
<blockquote cite="mid:542A6B9C.9030800@oracle.com" type="cite">
<br>
Hi Sangheon,
<br>
<br>
On 2014-09-30 01:30, Sangheon Kim wrote:
<br>
<blockquote type="cite">Hi all,
<br>
<br>
can I have reviews for the following small change to print
taskqueue statistics
<br>
for parallel gc, parNew and G1?
<br>
Main changes are:
<br>
1) printing by 'ParallelGCVerbose' flag, not 'PrintGCDetails
&& ParallelGCVerbose'.
<br>
2) printing logs via 'gclog_or_tty', not 'tty'.
<br>
3) adding 'totals' row to sums up.
<br>
<br>
CR:
<br>
<a class="moz-txt-link-freetext" href="https://bugs.openjdk.java.net/browse/JDK-8027428">https://bugs.openjdk.java.net/browse/JDK-8027428</a>
<br>
<br>
Webrev:
<br>
<a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~jwilhelm/8027428/">http://cr.openjdk.java.net/~jwilhelm/8027428/</a>
<br>
</blockquote>
<br>
Thanks for fixing this. Could you provide some examples of what
the output looks like for the different GCs now? It would make it
easier to review this if I had examples of the output for ParNew,
ParallelGC and G1.
<br>
</blockquote>
Here's examples of logs. (-XX:+ParallelGCVerbose
-XX:+PrintGCDetails)<br>
As you can see, ParNew and G1 has 'tot' while Parallel doesn't.<br>
<br>
1. ParallelGC: before applying this patch, BOLD 'tot' raw is absent.<br>
[2014-09-30T17:15:29.66] #1: [GC (Allocation Failure) == GC Tasks
Stats, GC 2<br>
[2014-09-30T17:15:29.66] thr qpush qpop qpop-s
qattempt qsteal opush omax<br>
[2014-09-30T17:15:29.66] --- ---------- ---------- ----------
---------- ---------- ---------- ----------<br>
[2014-09-30T17:15:29.66] 0 24213 23961 1101
848 847 0 0<br>
[2014-09-30T17:15:29.66] 1 22197 20795
85 47 46 0 0<br>
[2014-09-30T17:15:29.66] 2 22499 22147 932
703 702 0 0<br>
[2014-09-30T17:15:29.66] 3 20790 20492 956
710 709 0 0<br>
[2014-09-30T17:15:29.66] 4 0 0
0 0 0 0 0<br>
<u><b>[2014-09-30T17:15:29.66] tot 89699 87395
3074 2308 2304 0 0</b></u><br>
[2014-09-30T17:15:29.66] --------masked------- arrays
array<br>
[2014-09-30T17:15:29.66] thr push steal chunked
chunks<br>
[2014-09-30T17:15:29.66] --- ---------- ---------- ----------
----------<br>
[2014-09-30T17:15:29.66] 0 282 185 5
282<br>
[2014-09-30T17:15:29.66] 1 147 23 13
148<br>
[2014-09-30T17:15:29.66] 2 187 178 0
187<br>
[2014-09-30T17:15:29.66] 3 243 184 2
242<br>
[2014-09-30T17:15:29.66] 4 0 0
0 0<br>
<br>
2. ParNewGC<br>
[2014-09-30T17:26:47.08] #0: [GC (Allocation Failure) #0: [ParNewGC
Termination Stats<br>
[2014-09-30T17:26:47.08] elapsed --strong roots--
-------termination-------<br>
[2014-09-30T17:26:47.08] thr ms ms % ms
% attempts<br>
[2014-09-30T17:26:47.08] --- --------- --------- ------ ---------
------ --------<br>
[2014-09-30T17:26:47.08] 0 6.12 3.76 61.44 0.15
2.45 2<br>
[2014-09-30T17:26:47.08] 1 6.15 5.52 89.83 0.00
0.00 1<br>
[2014-09-30T17:26:47.08] 2 6.15 0.57 9.23 0.16
2.63 1<br>
[2014-09-30T17:26:47.08] 3 6.15 0.31 5.11 0.15
2.43 1<br>
[2014-09-30T17:26:47.08] GC Task Stats<br>
[2014-09-30T17:26:47.08] thr qpush qpop qpop-s
qattempt qsteal opush omax<br>
[2014-09-30T17:26:47.08] --- ---------- ---------- ----------
---------- ---------- ---------- ----------<br>
[2014-09-30T17:26:47.08] 0 26371 26041 462
130 128 0 0<br>
[2014-09-30T17:26:47.08] 1 9186 9138
0 1 0 0 0<br>
[2014-09-30T17:26:47.08] 2 12761 12591 834
287 286 0 0<br>
[2014-09-30T17:26:47.08] 3 17908 17755 930
288 287 0 0<br>
<u>[2014-09-30T17:26:47.08] tot 66226 65525
2226 706 701 0 0</u><br>
<br>
3. G1GC<br>
[2014-09-30T17:31:53.87] #0: [GC pause (G1 Evacuation Pause)
(young)GC Termination Stats<br>
[2014-09-30T17:31:53.87] elapsed --strong roots--
-------termination------- ------waste (KiB)------<br>
[2014-09-30T17:31:53.87] thr ms ms % ms
% attempts total alloc undo<br>
[2014-09-30T17:31:53.87] --- --------- --------- ------ ---------
------ -------- ------- ------- -------<br>
[2014-09-30T17:31:53.88] 2 3.63 0.01 0.20 0.00
0.09 13 0 0 0<br>
[2014-09-30T17:31:53.88] 3 3.65 0.01 0.18 0.00
0.08 13 0 0 0<br>
[2014-09-30T17:31:53.88] 1 3.71 0.02 0.46 0.00
0.06 5 0 0 0<br>
[2014-09-30T17:31:53.88] 0 6.83 2.32 34.01 0.00
0.00 1 0 0 0<br>
[2014-09-30T17:31:53.88] , 0.0077719 secs]<br>
[2014-09-30T17:31:53.88] [Parallel Time: 6.9 ms, GC Workers: 4]<br>
[2014-09-30T17:31:53.88] [GC Worker Start (ms): Min: 244.3,
Avg: 246.7, Max: 247.5, Diff: 3.1]<br>
[2014-09-30T17:31:53.88] [Ext Root Scanning (ms): Min: 0.0,
Avg: 0.4, Max: 1.7, Diff: 1.7, Sum: 1.8]<br>
[2014-09-30T17:31:53.88] [Update RS (ms): Min: 0.0, Avg: 0.0,
Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
[2014-09-30T17:31:53.88] [Processed Buffers: Min: 0, Avg:
0.0, Max: 0, Diff: 0, Sum: 0]<br>
[2014-09-30T17:31:53.88] [Scan RS (ms): Min: 0.0, Avg: 0.0,
Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
[2014-09-30T17:31:53.88] [Code Root Scanning (ms): Min: 0.0,
Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2]<br>
[2014-09-30T17:31:53.88] [Object Copy (ms): Min: 3.6, Avg:
3.9, Max: 4.8, Diff: 1.2, Sum: 15.7]<br>
[2014-09-30T17:31:53.88] [Termination (ms): Min: 0.0, Avg:
0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]<br>
[2014-09-30T17:31:53.88] [GC Worker Other (ms): Min: 0.0, Avg:
0.1, Max: 0.1, Diff: 0.0, Sum: 0.3]<br>
[2014-09-30T17:31:53.88] [GC Worker Total (ms): Min: 3.7, Avg:
4.5, Max: 6.8, Diff: 3.2, Sum: 17.9]<br>
[2014-09-30T17:31:53.88] [GC Worker End (ms): Min: 251.1, Avg:
251.1, Max: 251.2, Diff: 0.0]<br>
[2014-09-30T17:31:53.88] [Code Root Fixup: 0.1 ms]<br>
[2014-09-30T17:31:53.88] [Code Root Purge: 0.0 ms]<br>
[2014-09-30T17:31:53.88] [Clear CT: 0.1 ms]<br>
[2014-09-30T17:31:53.88] [Other: 0.8 ms]<br>
[2014-09-30T17:31:53.88] [Choose CSet: 0.0 ms]<br>
[2014-09-30T17:31:53.88] [Ref Proc: 0.6 ms]<br>
[2014-09-30T17:31:53.88] [Ref Enq: 0.1 ms]<br>
[2014-09-30T17:31:53.88] [Redirty Cards: 0.0 ms]<br>
[2014-09-30T17:31:53.88] [Humongous Reclaim: 0.0 ms]<br>
[2014-09-30T17:31:53.88] [Free CSet: 0.0 ms]<br>
[2014-09-30T17:31:53.88] [Eden: 14.0M(14.0M)->0.0B(18.0M)
Survivors: 0.0B->2048.0K Heap: 14.0M(64.0M)->2400.0K(64.0M)]<br>
[2014-09-30T17:31:53.88] GC Task Stats<br>
[2014-09-30T17:31:53.88] thr qpush qpop qpop-s
qattempt qsteal opush omax<br>
[2014-09-30T17:31:53.88] --- ---------- ---------- ----------
---------- ---------- ---------- ----------<br>
[2014-09-30T17:31:53.88] 0 53278 34205
10 2 0 0 0<br>
[2014-09-30T17:31:53.88] 1 8978 8672 4194
6843 6837 0 0<br>
[2014-09-30T17:31:53.88] 2 9325 9067 4222
6748 6734 0 0<br>
[2014-09-30T17:31:53.88] 3 8461 8212 3795
6329 6315 0 0<br>
<u>[2014-09-30T17:31:53.88] tot 80042 60156
12221 19922 19886 0 0</u><br>
[2014-09-30T17:31:53.88] [Times: user=0.02 sys=0.00 real=0.01 secs]<br>
<br>
<blockquote cite="mid:542A6B9C.9030800@oracle.com" type="cite">
<br>
I'm also wondering if we can have an even more descriptive
declaration of ParallelGCVerbose in globals.hpp. With your change
it says:
<br>
<br>
1532 product(bool, ParallelGCVerbose,
false, \
<br>
1533 "Print verbose collection statistics output for
parallel" \
<br>
1534
"collectors")
\
<br>
<br>
But there is a lot of logging that has to do with parallel work
(at least in G1) that is not controlled by this flag. It seems to
me that the flag actually only controls the task queue statistics.
Ideally we could change the name of the flag, but that will be too
much overhead I guess. But we can maybe updated the description to
indicate more what it actually controls.
<br>
</blockquote>
After applying this patch, I see this flag in 4 routines (3 files).<br>
And as all of them are stats for 'taskqueue' and 'termination', I
changed the description as a statistics related flag.<br>
But if it's not enough, may I ask your opinion?<br>
<br>
1. g1CollectedHeap.cpp<br>
a) TASKQUEUE_STATS_ONLY(if (ParallelGCVerbose)
print_taskqueue_stats());<br>
b) if (ParallelGCVerbose) {<br>
MutexLocker x(stats_lock());<br>
pss.print_termination_stats(worker_id);<br>
c) if (ParallelGCVerbose)
G1ParScanThreadState::print_termination_stats_hdr();<br>
2. parNewGeneration.cpp<br>
a) if (ParallelGCVerbose) {<br>
TASKQUEUE_STATS_ONLY(thread_state_set.print_termination_stats());<br>
TASKQUEUE_STATS_ONLY(thread_state_set.print_taskqueue_stats());<br>
3. psPromotionManager.cpp<br>
a) TASKQUEUE_STATS_ONLY(if (ParallelGCVerbose)
print_taskqueue_stats());<br>
<br>
Thanks,<br>
Sangheon<br>
<br>
<br>
<blockquote cite="mid:542A6B9C.9030800@oracle.com" type="cite">
<br>
Thanks,
<br>
Bengt
<br>
<br>
<blockquote type="cite">
<br>
Testing: jprt
<br>
<br>
Thanks,
<br>
Sangheon
<br>
</blockquote>
<br>
</blockquote>
<br>
</body>
</html>