RFR (S): JDK-8027428: Different conditions for printing taskqueue statistics for parallel gc, parNew and G1
Jesper Wilhelmsson
jesper.wilhelmsson at oracle.com
Tue Sep 30 20:58:35 UTC 2014
Hi,
Sangheon Kim skrev 30/9/14 19:41:
> 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?
I don't like that this flag controls some, but not all logging for parallel
Stuff. I think we should do one of the following:
A. Use ParallelGCVerbose for all verbose logging related to parallel stuff in
all GCs, or
B. Only use ParallelGCVerbose in ParallelGC.
There aren't that many occurrences of the flag so at least B doesn't seem to be
too much work. A is trickier since it involves finding all verbose logging
related to parallel stuff.
Keeping the flag as it is now and adding a description that says what it
controls is not an attractive option imho. Such a description will rapidly
become disinformation if the flag is used for some new logging. If it is too
much work to fix A or B, or any other viable solution in this change I would
prefer to keep the current slightly vague description (but remove the word
"output") and create a CR to fix the usage of the flag.
Thanks,
/Jesper
>
> 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
>>
>
More information about the hotspot-gc-dev
mailing list