January 2022 - zgc-dev

ZGC Concurrent Mark Work distribution
by Sundara Mohan M 10 Feb '22

10 Feb '22

Hi, We are using ZGC in production environment with following settings *[2022-01-27T09:12:55.684+0000][0.046s][info][gc,init] Version: 17.0.1+12 (release)* .. *[2022-01-27T09:12:55.684+0000][0.046s][info][gc,init] GC Workers: 18 (dynamic)* ... [2022-01-27T09:12:55.686+0000][0.048s][info][gc,init] Min Capacity: 64000M [2022-01-27T09:12:55.686+0000][0.048s][info][gc,init] Initial Capacity: 64000M *[2022-01-27T09:12:55.686+0000][0.048s][info][gc,init] Max Capacity: 64000M* [2022-01-27T09:12:55.686+0000][0.048s][info][gc,init] Medium Page Size: 32M [2022-01-27T09:12:55.686+0000][0.048s][info][gc,init] Pre-touch: Disabled [2022-01-27T09:12:55.686+0000][0.048s][info][gc,init] Available space on backing filesystem: N/A [2022-01-27T09:12:55.686+0000][0.048s][info][gc,init] Uncommit: Implicitly Disabled (-Xms equals -Xmx) *[2022-01-27T09:13:05.275+0000][9.636s][info][gc,init] Runtime Workers: 44* [2022-01-27T09:13:05.278+0000][9.640s][info][gc ] Using The Z Garbage Collector We run into GC cycle every 8-10 seconds. In some GC cycle Concurrent Mark phase is taking 2*s* and in some cycle it is taking 200*ms.* After enabling debug log for gc,phase saw in some cases more ZWorkers are doing work in other case it is given to only 1 or 2 ZWorker. Example log where work is done by multiple thread and took only 200ms [2022-01-27T18:51:41.324+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#12) 150.092ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#0) 1.059ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#0) 150.279ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#14) 1.055ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#14) 149.355ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#8) 1.060ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#8) 150.312ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#6) 1.060ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#6) 150.323ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#17) 1.062ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#11) 1.058ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#13) 1.060ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#2) 1.059ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#2) 150.423ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#13) 150.437ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#11) 150.374ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#3) 1.061ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#3) 150.537ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#7) 1.061ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#7) 150.550ms [2022-01-27T18:51:41.325+0000][34725.686s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#17) 150.364ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#15) 1.056ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#16) 1.059ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#1) 1.060ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#1) 150.613ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#4) 1.064ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#16) 150.584ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#10) 1.059ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#10) 150.706ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#4) 150.629ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#15) 150.601ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#9) 1.028ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#9) 150.938ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark Try Terminate (ZWorker#5) 1.057ms [2022-01-27T18:51:41.325+0000][34725.687s][debug][gc,phases ] GC(2927) Concurrent Mark (ZWorker#5) 151.063ms *[2022-01-27T18:51:41.325+0000][34725.687s][info ][gc,phases ] GC(2927) Concurrent Mark 204.119ms* Another case where it was run by only 1/2 worker and took 1/2s respectively ... *[2022-01-27T18:51:52.342+0000][34736.704s][debug][gc,phases ] GC(2928) Concurrent Mark (ZWorker#12) 934.304ms* [2022-01-27T18:51:52.342+0000][34736.704s][debug][gc,phases ] GC(2928) Concurrent Mark Try Terminate (ZWorker#14) 1.062ms *[2022-01-27T18:51:52.342+0000][34736.704s][debug][gc,phases ] GC(2928) Concurrent Mark (ZWorker#14) 934.339ms* *[2022-01-27T18:51:52.342+0000][34736.704s][info ][gc,phases ] GC(2928) Concurrent Mark 1021.048ms* [2022-01-27T18:52:00.822+0000][34745.184s][info ][safepoint ] Safepoint "ZMarkStart", Time since last: 8436197260 ns, Reaching safepoint: 1019671 ns, At safepoint: 515965 ns, Total: 1 535636 ns [2022-01-27T18:52:00.835+0000][34745.197s][debug][gc,phases ] GC(2929) Concurrent Roots OopStorageSet (ZWorker#5) 0.991ms [2022-01-27T18:52:00.851+0000][34745.213s][debug][gc,phases ] GC(2929) Concurrent Roots ClassLoaderDataGraph (ZWorker#5) 15.777ms [2022-01-27T18:52:00.864+0000][34745.226s][debug][gc,phases ] GC(2929) Concurrent Roots JavaThreads (ZWorker#5) 12.769ms [2022-01-27T18:52:00.945+0000][34745.307s][debug][gc,phases ] GC(2929) Concurrent Roots CodeCache (ZWorker#5) 81.380ms [2022-01-27T18:52:02.766+0000][34747.127s][debug][gc,phases ] GC(2929) Concurrent Mark Try Flush (ZWorker#16) 1.613ms [2022-01-27T18:52:02.771+0000][34747.133s][debug][gc,phases ] GC(2929) Concurrent Mark Try Flush (ZWorker#16) 0.717ms [2022-01-27T18:52:02.771+0000][34747.133s][debug][gc,phases ] GC(2929) Concurrent Mark Try Flush (ZWorker#16) 0.292ms [2022-01-27T18:52:02.771+0000][34747.133s][debug][gc,phases ] GC(2929) Concurrent Mark Try Terminate (ZWorker#16) 0.306ms [2022-01-27T18:52:02.771+0000][34747.133s][debug][gc,phases ] GC(2929) Concurrent Mark Try Terminate (ZWorker#16) 0.000ms *[2022-01-27T18:52:02.771+0000][34747.133s][debug][gc,phases ] GC(2929) Concurrent Mark (ZWorker#16) 1825.719ms[2022-01-27T18:52:02.771+0000][34747.133s][info ][gc,phases ] GC(2929) Concurrent Mark 1949.325ms* Even though we have 18 threads, does anyone have any idea why the work is not distributed among multiple workers? Thanks Sundar

2 10

ZGC unstable behaviour on java 17
by Anatoly Deyneka 27 Jan '22

27 Jan '22

We are running a GC intensive application with allocation rate up to 1.5GB/s(4k requests/sec) on 32v cores instance (-Xms20G -Xmx20G). openjdk 17 2021-09-14 OpenJDK Runtime Environment (build 17+35-2724) OpenJDK 64-Bit Server VM (build 17+35-2724, mixed mode, sharing) During migration from java 15 to java 17 we see unstable behavior when zgc goes to infinite loop and doesn't return back to the normal state. We see the following behavior: - it runs perfectly(~30% better then on java 15) - 5-7GB used memory with 16% CPU utilization - something happens and CPU utilization jumps to 40%, used memory jumps to 19GB, zgc cycles time is increased in 10times - sometimes app works about 30min before the crash sometimes it's crashed instantly - if it's still alive memory is not released and the app works with used memory 18-20GB - we see allocation stalls - we see the following GC stats [17606.140s][info][gc,phases ] GC(719) Concurrent Process Non-Strong References 25781.928ms [17610.181s][info][gc,stats ] Subphase: Concurrent Classes Unlink 14280.772 / 25769.511 1126.563 / 25769.511 217.882 / 68385.750 217.882 / 68385.750 ms - we see JVM starts massively unload classes (jvm_classes_unloaded_total counter keep increasing) . - we’ve managed to profile JVM in such ‘unstable’ state and see ZTask consuming a lot of cpu doing CompiledMethod::unload_nmethod_caches(bool) job. See attached image. We played with options: -XX:ZCollectionInterval=5 -XX:SoftMaxHeapSize=12G -XX:ZAllocationSpikeTolerance=4 -XX:MetaspaceReclaimPolicy=aggressive But it doesn't help. it just postpones this event. Only if we redirect traffic to another node it goes to normal. Regards, Anatoly Deyneka [image: image.png] [image: image.png] [image: image.png]

4 15

ZGC AArch64 hang on SPECjbb2015
by 逯晓威(峰风) 14 Jan '22

14 Jan '22

Hi, I have tested zgc on jdk-15-GA and found occasionally SPECjbb2015 hangs when it is about to shut down. This is quite hard to reproduce, one out of 20 iterations probably. Since it only reproduces during shut down, I prefer to use "preset" mode to run SPECjbb to save time. jdk-15-GA/bin/java -XX:+UseZGC -Xmx10g -Dspecjbb.controller.type=PRESET -Dspecjbb.controller.preset.ir=20000 -Dspecjbb.controller.preset.duration=60000 -jar specjbb2015.jar -m COMPOSITE And SPECjbb log is as follow: <Tue Jan 04 03:06:13 EST 2022> org.spec.jbb: Failed to stop executor service java.util.concurrent.ForkJoinPool@9d2cbbc[Terminating, parallelism = 160, size = 2, active = 0, running = 2, steals = 40255, tasks = 0, submissions = 0], trying again <Tue Jan 04 03:06:14 EST 2022> org.spec.jbb: Failed to stop executor service java.util.concurrent.ForkJoinPool@9d2cbbc[Terminating, parallelism = 160, size = 2, active = 0, running = 2, steals = 40255, tasks = 0, submissions = 0], trying again This seems quite similar to a previous issue: https://bugs.openjdk.java.net/browse/JDK-8214285, but on AArch64 other than Skylake. In addition, JDK-8214285 has been solved in jdk12, but we reproduced this issue on jdk-13.0.2+8 and jdk-14.0.2+12 Regards,Xiaowei Lu

2 2