-
Bug
-
Resolution: Fixed
-
P4
-
11, 12, 13, 14
-
b10
Issue | Fix Version | Assignee | Priority | Status | Resolution | Resolved In Build |
---|---|---|---|---|---|---|
JDK-8245207 | 13.0.4 | Per Liden | P4 | Resolved | Fixed | b02 |
JDK-8229942 | 11.0.5 | Per Liden | P4 | Resolved | Fixed | b05 |
From Hao Tang <albert.th@alibaba-inc.com>:
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
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
- backported by
-
JDK-8229942 ZGC: Fix incorrect statistics
-
- Resolved
-
-
JDK-8245207 ZGC: Fix incorrect statistics
-
- Resolved
-