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 23:50:15 UTC 2014
Hi Jesper,
Thank you for reviewing this.
On 09/30/2014 01:58 PM, Jesper Wilhelmsson wrote:
> 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.
Agree with that vague description(w/o "output") would be better in this
case.
Does anyone have an opinion on this description change?
Thanks,
Sangheon
>
> 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