ZGC Concurrent Mark Work distribution
Sundara Mohan M
m.sundar85 at gmail.com
Thu Jan 27 19:00:17 UTC 2022
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
More information about the zgc-dev
mailing list