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