Information on how to parse/interpret ZGC Logs
Prabhash Rathore
prabhashrathore at gmail.com
Mon Feb 3 05:52:00 UTC 2020
Hello,
We have decided to use ZGC Garbage Collector for our Java application
running on Java 11. I was wondering if there are any tools or any
documenation on how to interpret ZGC logs.
I found following statistics in ZGC log which as per my understanding shows
a very large allocation stall of 3902042.342 milliseconds. It will be
really great if I can get some help to understand this further.
[2020-02-02T22:37:36.883+0000] === Garbage Collection Statistics
=======================================================================================================================
[2020-02-02T22:37:36.883+0000]
Last 10s Last 10m Last 10h
Total
[2020-02-02T22:37:36.883+0000]
Avg / Max Avg / Max Avg / Max
Avg / Max
[2020-02-02T22:37:36.883+0000] Collector: Garbage Collection Cycle
0.000 / 0.000 7789.187 / 7789.187 12727.424 /
3903938.012 1265.033 / 3903938.012 ms
[2020-02-02T22:37:36.883+0000] Contention: Mark Segment Reset Contention
0 / 0 10 / 1084 176 / 15122
42 / 15122 ops/s
[2020-02-02T22:37:36.883+0000] Contention: Mark SeqNum Reset Contention
0 / 0 0 / 5 0 / 31
0 / 31 ops/s
[2020-02-02T22:37:36.883+0000] Contention: Relocation Contention
0 / 0 0 / 3 1 / 708
7 / 890 ops/s
[2020-02-02T22:37:36.883+0000] Critical: Allocation Stall
0.000 / 0.000 0.000 / 0.000 6714.722 /
3902042.342 6714.722 / 3902042.342 ms
[2020-02-02T22:37:36.883+0000] Critical: Allocation Stall
0 / 0 0 / 0 12 / 4115
2 / 4115 ops/s
[2020-02-02T22:37:36.883+0000] Critical: GC Locker Stall
0.000 / 0.000 0.000 / 0.000 3.979 / 6.561
1.251 / 6.561 ms
[2020-02-02T22:37:36.883+0000] Critical: GC Locker Stall
0 / 0 0 / 0 0 / 1
0 / 1 ops/s
[2020-02-02T22:37:36.883+0000] Memory: Allocation Rate
0 / 0 6 / 822 762 / 25306
1548 / 25306 MB/s
[2020-02-02T22:37:36.883+0000] Memory: Heap Used After Mark
0 / 0 92170 / 92170 89632 / 132896
30301 / 132896 MB
[2020-02-02T22:37:36.883+0000] Memory: Heap Used After Relocation
0 / 0 76376 / 76376 67490 / 132928
8047 / 132928 MB
[2020-02-02T22:37:36.883+0000] Memory: Heap Used Before Mark
0 / 0 92128 / 92128 84429 / 132896
29452 / 132896 MB
[2020-02-02T22:37:36.883+0000] Memory: Heap Used Before Relocation
0 / 0 86340 / 86340 76995 / 132896
15862 / 132896 MB
[2020-02-02T22:37:36.883+0000] Memory: Out Of Memory
0 / 0 0 / 0 0 / 0
0 / 0 ops/s
[2020-02-02T22:37:36.883+0000] Memory: Page Cache Flush
0 / 0 0 / 0 62 / 2868
16 / 2868 MB/s
[2020-02-02T22:37:36.883+0000] Memory: Page Cache Hit L1
0 / 0 7 / 2233 277 / 11553
583 / 11553 ops/s
[2020-02-02T22:37:36.883+0000] Memory: Page Cache Hit L2
0 / 0 0 / 0 20 / 4619
59 / 4619 ops/s
[2020-02-02T22:37:36.883+0000] Memory: Page Cache Miss
0 / 0 0 / 0 15 / 1039
3 / 1297 ops/s
[2020-02-02T22:37:36.883+0000] Memory: Undo Object Allocation Failed
0 / 0 0 / 0 0 / 24
0 / 24 ops/s
[2020-02-02T22:37:36.883+0000] Memory: Undo Object Allocation
Succeeded 0 / 0 0 / 3 1 /
708 7 / 890 ops/s
[2020-02-02T22:37:36.883+0000] Memory: Undo Page Allocation
0 / 0 0 / 12 30 / 3464
7 / 3464 ops/s
[2020-02-02T22:37:36.883+0000] Phase: Concurrent Destroy Detached
Pages 0.000 / 0.000 0.004 / 0.004 11.675 /
1484.886 1.155 / 1484.886 ms
[2020-02-02T22:37:36.883+0000] Phase: Concurrent Mark
0.000 / 0.000 7016.569 / 7016.569 11758.365 /
3901893.544 1103.558 / 3901893.544 ms
[2020-02-02T22:37:36.883+0000] Phase: Concurrent Mark Continue
0.000 / 0.000 0.000 / 0.000 1968.844 / 3674.454
1968.844 / 3674.454 ms
[2020-02-02T22:37:36.883+0000] Phase: Concurrent Prepare Relocation
Set 0.000 / 0.000 453.732 / 453.732 364.535 /
7103.720 39.453 / 7103.720 ms
[2020-02-02T22:37:36.883+0000] Phase: Concurrent Process Non-Strong
References 0.000 / 0.000 2.003 / 2.003 2.738 / 34.406
2.253 / 34.406 ms
[2020-02-02T22:37:36.883+0000] Phase: Concurrent Relocate
0.000 / 0.000 261.822 / 261.822 335.954 / 2207.669
45.868 / 2207.669 ms
[2020-02-02T22:37:36.883+0000] Phase: Concurrent Reset Relocation Set
0.000 / 0.000 6.083 / 6.083 13.489 / 1128.678
3.574 / 1128.678 ms
[2020-02-02T22:37:36.883+0000] Phase: Concurrent Select Relocation
Set 0.000 / 0.000 6.379 / 6.379 97.530 /
1460.679 18.439 / 1460.679 ms
[2020-02-02T22:37:36.883+0000] Phase: Pause Mark End
0.000 / 0.000 4.420 / 4.420 6.219 / 26.498
6.474 / 40.883 ms
[2020-02-02T22:37:36.883+0000] Phase: Pause Mark Start
0.000 / 0.000 14.836 / 14.836 11.893 / 28.350
11.664 / 41.767 ms
[2020-02-02T22:37:36.884+0000] Phase: Pause Relocate Start
0.000 / 0.000 13.411 / 13.411 30.849 / 697.344
11.995 / 697.344 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent Mark
0.000 / 0.000 7015.793 / 7016.276 18497.265 /
3901893.075 1690.497 / 3901893.075 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent Mark Idle
0.000 / 0.000 1.127 / 13.510 1.292 / 219.999
1.280 / 219.999 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent Mark Try Flush
0.000 / 0.000 1.295 / 2.029 47.094 / 34869.359
4.797 / 34869.359 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent Mark Try Terminate
0.000 / 0.000 1.212 / 14.847 1.760 / 3799.238
1.724 / 3799.238 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent References Enqueue
0.000 / 0.000 0.009 / 0.009 0.022 / 1.930
0.017 / 2.350 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent References Process
0.000 / 0.000 0.599 / 0.599 0.768 / 23.966
0.495 / 23.966 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent Weak Roots
0.000 / 0.000 0.882 / 1.253 1.155 / 21.699
1.077 / 23.602 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent Weak Roots
JNIWeakHandles 0.000 / 0.000 0.301 / 0.943 0.308 /
10.868 0.310 / 23.219 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent Weak Roots
StringTable 0.000 / 0.000 0.289 / 0.496 0.390 /
12.794 0.363 / 22.907 ms
[2020-02-02T22:37:36.884+0000] Subphase: Concurrent Weak Roots
VMWeakHandles 0.000 / 0.000 0.230 / 0.469 0.329 /
21.267 0.331 / 23.135 ms
[2020-02-02T22:37:36.884+0000] Subphase: Pause Mark Try Complete
0.000 / 0.000 0.000 / 0.000 0.501 / 4.801
0.480 / 17.208 ms
[2020-02-02T22:37:36.884+0000] Subphase: Pause Remap TLABS
0.000 / 0.000 0.252 / 0.252 0.195 / 0.528
0.226 / 3.451 ms
[2020-02-02T22:37:36.884+0000] Subphase: Pause Retire TLABS
0.000 / 0.000 1.195 / 1.195 1.324 / 5.082
1.408 / 11.219 ms
[2020-02-02T22:37:36.884+0000] Subphase: Pause Roots
0.000 / 0.000 6.968 / 10.865 12.329 / 693.701
6.431 / 1300.994 ms
[2020-02-02T22:37:36.884+0000] Subphase: Pause Roots
ClassLoaderDataGraph 0.000 / 0.000 4.819 / 8.232
9.635 / 693.405 3.476 / 693.405 ms
[2020-02-02T22:37:36.884+0000] Subphase: Pause Roots CodeCache
0.000 / 0.000 0.842 / 2.731 0.996 / 83.553
0.780 / 83.553 ms
[2020-02-02T22:37:36.884+0000] Subphase: Pause Roots JNIHandles
0.000 / 0.000 1.171 / 6.314 0.866 / 17.875
0.837 / 25.708 ms
Thank you!
Prabhash Rathore
More information about the zgc-dev
mailing list