回复：ZGC: Fix an incorrect column in GC statistics
Hao Tang
albert.th at alibaba-inc.com
Tue Aug 13 01:29:41 UTC 2019
Cheers, Per and Erik. Thanks for your help.
Sincerely,
Hao Tang
------------------------------------------------------------------
发件人：Per Liden <per.liden at oracle.com>
发送时间：2019年8月12日(星期一) 17:49
收件人："Erik Österlund" <erik.osterlund at oracle.com>; 唐浩(纷至) <albert.th at alibaba-inc.com>; zgc-dev <zgc-dev at openjdk.java.net>; hotspot-gc-dev openjdk.java.net <hotspot-gc-dev at openjdk.java.net>
主 题：Re: ZGC: Fix an incorrect column in GC statistics
Pushed.
https://hg.openjdk.java.net/jdk/jdk/rev/8ebc8f74f2d2
cheers,
Per
On 8/12/19 10:50 AM, Erik Österlund wrote:
> 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 zgc-dev
mailing list