RFR (S): JDK-8027428: Different conditions for printing taskqueue statistics for parallel gc, parNew and G1
Sangheon Kim
sangheon.kim at oracle.com
Tue Sep 30 17:41:47 UTC 2014
Hi Bengt,
Thank you for looking at this change.
On 09/30/2014 01:36 AM, Bengt Rutisson wrote:
>
> Hi Sangheon,
>
> On 2014-09-30 01:30, Sangheon Kim wrote:
>> Hi all,
>>
>> can I have reviews for the following small change to print taskqueue
>> statistics
>> for parallel gc, parNew and G1?
>> Main changes are:
>> 1) printing by 'ParallelGCVerbose' flag, not 'PrintGCDetails &&
>> ParallelGCVerbose'.
>> 2) printing logs via 'gclog_or_tty', not 'tty'.
>> 3) adding 'totals' row to sums up.
>>
>> CR:
>> https://bugs.openjdk.java.net/browse/JDK-8027428
>>
>> Webrev:
>> http://cr.openjdk.java.net/~jwilhelm/8027428/
>
> 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.
Here's examples of logs. (-XX:+ParallelGCVerbose -XX:+PrintGCDetails)
As you can see, ParNew and G1 has 'tot' while Parallel doesn't.
1. ParallelGC: before applying this patch, BOLD 'tot' raw is absent.
[2014-09-30T17:15:29.66] #1: [GC (Allocation Failure) == GC Tasks Stats,
GC 2
[2014-09-30T17:15:29.66] thr qpush qpop qpop-s
qattempt qsteal opush omax
[2014-09-30T17:15:29.66] --- ---------- ---------- ---------- ----------
---------- ---------- ----------
[2014-09-30T17:15:29.66] 0 24213 23961 1101 848
847 0 0
[2014-09-30T17:15:29.66] 1 22197 20795 85 47
46 0 0
[2014-09-30T17:15:29.66] 2 22499 22147 932 703
702 0 0
[2014-09-30T17:15:29.66] 3 20790 20492 956 710
709 0 0
[2014-09-30T17:15:29.66] 4 0 0 0 0
0 0 0
_*[2014-09-30T17:15:29.66] tot 89699 87395 3074
2308 2304 0 0*_
[2014-09-30T17:15:29.66] --------masked------- arrays array
[2014-09-30T17:15:29.66] thr push steal chunked chunks
[2014-09-30T17:15:29.66] --- ---------- ---------- ---------- ----------
[2014-09-30T17:15:29.66] 0 282 185 5 282
[2014-09-30T17:15:29.66] 1 147 23 13 148
[2014-09-30T17:15:29.66] 2 187 178 0 187
[2014-09-30T17:15:29.66] 3 243 184 2 242
[2014-09-30T17:15:29.66] 4 0 0 0 0
2. ParNewGC
[2014-09-30T17:26:47.08] #0: [GC (Allocation Failure) #0: [ParNewGC
Termination Stats
[2014-09-30T17:26:47.08] elapsed --strong roots--
-------termination-------
[2014-09-30T17:26:47.08] thr ms ms % ms % attempts
[2014-09-30T17:26:47.08] --- --------- --------- ------ --------- ------
--------
[2014-09-30T17:26:47.08] 0 6.12 3.76 61.44 0.15
2.45 2
[2014-09-30T17:26:47.08] 1 6.15 5.52 89.83 0.00
0.00 1
[2014-09-30T17:26:47.08] 2 6.15 0.57 9.23 0.16
2.63 1
[2014-09-30T17:26:47.08] 3 6.15 0.31 5.11 0.15
2.43 1
[2014-09-30T17:26:47.08] GC Task Stats
[2014-09-30T17:26:47.08] thr qpush qpop qpop-s
qattempt qsteal opush omax
[2014-09-30T17:26:47.08] --- ---------- ---------- ---------- ----------
---------- ---------- ----------
[2014-09-30T17:26:47.08] 0 26371 26041 462 130
128 0 0
[2014-09-30T17:26:47.08] 1 9186 9138 0 1
0 0 0
[2014-09-30T17:26:47.08] 2 12761 12591 834 287
286 0 0
[2014-09-30T17:26:47.08] 3 17908 17755 930 288
287 0 0
_[2014-09-30T17:26:47.08] tot 66226 65525 2226
706 701 0 0_
3. G1GC
[2014-09-30T17:31:53.87] #0: [GC pause (G1 Evacuation Pause) (young)GC
Termination Stats
[2014-09-30T17:31:53.87] elapsed --strong roots--
-------termination------- ------waste (KiB)------
[2014-09-30T17:31:53.87] thr ms ms % ms %
attempts total alloc undo
[2014-09-30T17:31:53.87] --- --------- --------- ------ --------- ------
-------- ------- ------- -------
[2014-09-30T17:31:53.88] 2 3.63 0.01 0.20 0.00
0.09 13 0 0 0
[2014-09-30T17:31:53.88] 3 3.65 0.01 0.18 0.00
0.08 13 0 0 0
[2014-09-30T17:31:53.88] 1 3.71 0.02 0.46 0.00
0.06 5 0 0 0
[2014-09-30T17:31:53.88] 0 6.83 2.32 34.01 0.00
0.00 1 0 0 0
[2014-09-30T17:31:53.88] , 0.0077719 secs]
[2014-09-30T17:31:53.88] [Parallel Time: 6.9 ms, GC Workers: 4]
[2014-09-30T17:31:53.88] [GC Worker Start (ms): Min: 244.3, Avg:
246.7, Max: 247.5, Diff: 3.1]
[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]
[2014-09-30T17:31:53.88] [Update RS (ms): Min: 0.0, Avg: 0.0, Max:
0.0, Diff: 0.0, Sum: 0.0]
[2014-09-30T17:31:53.88] [Processed Buffers: Min: 0, Avg: 0.0,
Max: 0, Diff: 0, Sum: 0]
[2014-09-30T17:31:53.88] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max:
0.0, Diff: 0.0, Sum: 0.0]
[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]
[2014-09-30T17:31:53.88] [Object Copy (ms): Min: 3.6, Avg: 3.9,
Max: 4.8, Diff: 1.2, Sum: 15.7]
[2014-09-30T17:31:53.88] [Termination (ms): Min: 0.0, Avg: 0.0,
Max: 0.0, Diff: 0.0, Sum: 0.0]
[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]
[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]
[2014-09-30T17:31:53.88] [GC Worker End (ms): Min: 251.1, Avg:
251.1, Max: 251.2, Diff: 0.0]
[2014-09-30T17:31:53.88] [Code Root Fixup: 0.1 ms]
[2014-09-30T17:31:53.88] [Code Root Purge: 0.0 ms]
[2014-09-30T17:31:53.88] [Clear CT: 0.1 ms]
[2014-09-30T17:31:53.88] [Other: 0.8 ms]
[2014-09-30T17:31:53.88] [Choose CSet: 0.0 ms]
[2014-09-30T17:31:53.88] [Ref Proc: 0.6 ms]
[2014-09-30T17:31:53.88] [Ref Enq: 0.1 ms]
[2014-09-30T17:31:53.88] [Redirty Cards: 0.0 ms]
[2014-09-30T17:31:53.88] [Humongous Reclaim: 0.0 ms]
[2014-09-30T17:31:53.88] [Free CSet: 0.0 ms]
[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)]
[2014-09-30T17:31:53.88] GC Task Stats
[2014-09-30T17:31:53.88] thr qpush qpop qpop-s
qattempt qsteal opush omax
[2014-09-30T17:31:53.88] --- ---------- ---------- ---------- ----------
---------- ---------- ----------
[2014-09-30T17:31:53.88] 0 53278 34205 10
2 0 0 0
[2014-09-30T17:31:53.88] 1 8978 8672 4194 6843
6837 0 0
[2014-09-30T17:31:53.88] 2 9325 9067 4222 6748
6734 0 0
[2014-09-30T17:31:53.88] 3 8461 8212 3795 6329
6315 0 0
_[2014-09-30T17:31:53.88] tot 80042 60156 12221
19922 19886 0 0_
[2014-09-30T17:31:53.88] [Times: user=0.02 sys=0.00 real=0.01 secs]
>
> I'm also wondering if we can have an even more descriptive declaration
> of ParallelGCVerbose in globals.hpp. With your change it says:
>
> 1532 product(bool, ParallelGCVerbose,
> false, \
> 1533 "Print verbose collection statistics output for
> parallel" \
> 1534 "collectors") \
>
> 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.
After applying this patch, I see this flag in 4 routines (3 files).
And as all of them are stats for 'taskqueue' and 'termination', I
changed the description as a statistics related flag.
But if it's not enough, may I ask your opinion?
1. g1CollectedHeap.cpp
a) TASKQUEUE_STATS_ONLY(if (ParallelGCVerbose) print_taskqueue_stats());
b) if (ParallelGCVerbose) {
MutexLocker x(stats_lock());
pss.print_termination_stats(worker_id);
c) if (ParallelGCVerbose)
G1ParScanThreadState::print_termination_stats_hdr();
2. parNewGeneration.cpp
a) if (ParallelGCVerbose) {
TASKQUEUE_STATS_ONLY(thread_state_set.print_termination_stats());
TASKQUEUE_STATS_ONLY(thread_state_set.print_taskqueue_stats());
3. psPromotionManager.cpp
a) TASKQUEUE_STATS_ONLY(if (ParallelGCVerbose) print_taskqueue_stats());
Thanks,
Sangheon
>
> Thanks,
> Bengt
>
>>
>> Testing: jprt
>>
>> Thanks,
>> Sangheon
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20140930/90f2d106/attachment.htm>
More information about the hotspot-gc-dev
mailing list