ZGC: Fix an incorrect column in GC statistics

Erik Österlund erik.osterlund at oracle.com
Mon Aug 12 08:50:49 UTC 2019


Hi,

Looks good to me too.

/Erik

On 2019-08-11 11:07, Per Liden wrote:
> Hi,
> 
> Nice catch! Change looks good. As far as I can tell there's no JIRA 
> entry for this yet, so I'll create one and sponsor your fix.
> 
> thanks,
> Per
> 
> On 2019-08-11 02:16, Hao Tang wrote:
>> Hi, I found that column "total" of ZGC log's statistics always reports 
>> obviously incorrect average values after running program with ZGC for 
>> over 10 hours (36000s). See the GC log below.
>>
>> [36000.080s][info][gc,stats    ] === Garbage Collection Statistics 
>> ======================================================================================================================= 
>>
>> [36000.080s][info][gc,stats    
>> ]                                                              Last 
>> 10s              Last 10m              Last 10h                Total
>> [36000.080s][info][gc,stats    
>> ]                                                              Avg / 
>> Max             Avg / Max             Avg / Max             Avg / Max
>> [36000.080s][info][gc,stats    ]   Collector: Garbage Collection 
>> Cycle                     33.269 / 34.686       32.699 / 36.862       
>> 32.938 / 60.703        0.000 / 60.703      ms
>> [36000.080s][info][gc,stats    ]  Contention: Mark Segment Reset 
>> Contention                     0 / 0                 0 / 
>> 0                 0 / 0                 1 / 0           ops/s
>> [36000.080s][info][gc,stats    ]  Contention: Mark SeqNum Reset 
>> Contention                      0 / 0                 0 / 
>> 0                 0 / 0                 1 / 0           ops/s
>> [36000.080s][info][gc,stats    ]  Contention: Relocation 
>> Contention                             0 / 0                 0 / 
>> 0                 0 / 2277              1 / 2277        ops/s
>> [36000.080s][info][gc,stats    ]    Critical: Allocation 
>> Stall                              0.000 / 0.000         0.000 / 
>> 0.000         0.000 / 0.000         0.000 / 0.000       ms
>> [36000.080s][info][gc,stats    ]    Critical: Allocation 
>> Stall                                  0 / 0                 0 / 
>> 0                 0 / 0                 1 / 0           ops/s
>> [36000.080s][info][gc,stats    ]    Critical: GC Locker 
>> Stall                               0.000 / 0.000         0.000 / 
>> 0.000         0.000 / 0.000         0.000 / 0.000       ms
>> [36000.080s][info][gc,stats    ]    Critical: GC Locker 
>> Stall                                   0 / 0                 0 / 
>> 0                 0 / 0                 1 / 0           ops/s
>> [36000.080s][info][gc,stats    ]      Memory: Allocation 
>> Rate                                  45 / 48               45 / 
>> 48               45 / 90                0 / 90          MB/s
>> [36000.080s][info][gc,stats    ]      Memory: Heap Used After 
>> Mark                            126 / 130             125 / 
>> 140             125 / 164               0 / 164         MB
>> [36000.080s][info][gc,stats    ]      Memory: Heap Used After 
>> Relocation                       48 / 52               47 / 
>> 52               47 / 54                0 / 54          MB
>> [36000.080s][info][gc,stats    ]      Memory: Heap Used Before 
>> Mark                           124 / 130             123 / 
>> 138             124 / 158               0 / 158         MB
>> [36000.080s][info][gc,stats    ]      Memory: Heap Used Before 
>> Relocation                      54 / 58               53 / 
>> 60               53 / 60                0 / 60          MB
>>
>> The bug is caused by mistakenly adding "nsamples" to 
>> ZStatSamplerData::_sum. I am applying the patch below to fix the bug. 
>> Please give advice on this fix.
>> diff -r 8f067351c370 src/hotspot/share/gc/z/zStat.cpp
>> --- a/src/hotspot/share/gc/z/zStat.cpp Mon Aug 05 16:27:30 2019 -0700
>> +++ b/src/hotspot/share/gc/z/zStat.cpp Fri Aug 09 11:22:58 2019 +0800
>> @@ -63,7 +63,7 @@
>>    void add(const ZStatSamplerData& new_sample) {
>>      _nsamples += new_sample._nsamples;
>> -    _sum += new_sample._nsamples;
>> +    _sum += new_sample._sum;
>>      _max = MAX2(_max, new_sample._max);
>>    }
>> };
>> This patch can enable ZGC to print correct statistics after 10 hours.
>>
>> [36000.080s][info][gc,stats    ] === Garbage Collection Statistics 
>> ======================================================================================================================= 
>>
>> [36000.080s][info][gc,stats    
>> ]                                                              Last 
>> 10s              Last 10m              Last 10h                Total
>> [36000.080s][info][gc,stats    
>> ]                                                              Avg / 
>> Max             Avg / Max             Avg / Max             Avg / Max
>> [36000.080s][info][gc,stats    ]   Collector: Garbage Collection 
>> Cycle                     32.794 / 32.985       32.865 / 38.454       
>> 33.212 / 80.477       33.212 / 80.477      ms
>> [36000.080s][info][gc,stats    ]  Contention: Mark Segment Reset 
>> Contention                     0 / 0                 0 / 
>> 0                 0 / 0                 0 / 0           ops/s
>> [36000.080s][info][gc,stats    ]  Contention: Mark SeqNum Reset 
>> Contention                      0 / 0                 0 / 
>> 0                 0 / 0                 0 / 0           ops/s
>> [36000.080s][info][gc,stats    ]  Contention: Relocation 
>> Contention                             0 / 0                 0 / 
>> 0                 0 / 5978              0 / 5978        ops/s
>> [36000.080s][info][gc,stats    ]    Critical: Allocation 
>> Stall                              0.000 / 0.000         0.000 / 
>> 0.000         0.000 / 0.000         0.000 / 0.000       ms
>> [36000.080s][info][gc,stats    ]    Critical: Allocation 
>> Stall                                  0 / 0                 0 / 
>> 0                 0 / 0                 0 / 0           ops/s
>> [36000.080s][info][gc,stats    ]    Critical: GC Locker 
>> Stall                               0.000 / 0.000         0.000 / 
>> 0.000         0.000 / 0.000         0.000 / 0.000       ms
>> [36000.080s][info][gc,stats    ]    Critical: GC Locker 
>> Stall                                   0 / 0                 0 / 
>> 0                 0 / 0                 0 / 0           ops/s
>> [36000.080s][info][gc,stats    ]      Memory: Allocation 
>> Rate                                  45 / 46               45 / 
>> 48               45 / 92               45 / 92          MB/s
>> [36000.080s][info][gc,stats    ]      Memory: Heap Used After 
>> Mark                            124 / 126             125 / 
>> 148             126 / 164             126 / 164         MB
>> [36000.080s][info][gc,stats    ]      Memory: Heap Used After 
>> Relocation                       48 / 52               48 / 
>> 52               47 / 54               47 / 54          MB
>> [36000.080s][info][gc,stats    ]      Memory: Heap Used Before 
>> Mark                           122 / 124             123 / 
>> 148             124 / 158             124 / 158         MB
>> [36000.080s][info][gc,stats    ]      Memory: Heap Used Before 
>> Relocation                      54 / 58               54 / 
>> 60               53 / 60               53 / 60          MB
>>
>>
>> Best regards,
>> Hao Tang
>>


More information about the hotspot-gc-dev mailing list