ZGC Concurrent Mark Work distribution
Per Liden
per.liden at oracle.com
Mon Jan 31 08:35:41 UTC 2022
Hi,
It's hard to tell without seeing the complete GC log, but I suspect that
the heuristics just picks different number of threads here. The
heuristics will pick the number of threads currently needed, based on
available memory, allocation rate, etc. Each GC cycle will print "Using
XX workers" in the log. I wrote about this feature in my latest blog
post under "Dynamic Number of GC Threads"
(https://malloc.se/blog/zgc-jdk17).
cheers,
Per
On 1/27/22 20:20, Sundara Mohan M wrote:
> Adding complete log of that phase in case if it helps
> -01-27T18:51:41.121+0000][34725.483s][info ][gc,phases ] GC(2927) Pause
> Mark Start 0.046ms
> [2022-01-27T18:51:41.121+0000][34725.483s][info ][safepoint ] Safepoint
> "ZMarkStart", Time since last: 8392610571 ns, Reaching safepoint: 606586
> ns, At safepoint: 438685 ns, Total: 1045271 ns
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#11) 0.000ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#8) 0.102ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#0) 0.110ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#2) 0.062ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#9) 0.183ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#13) 0.209ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#6) 0.001ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#1) 0.098ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#12) 0.109ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#5) 0.112ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#17) 0.000ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#15) 0.103ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#16) 0.147ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#7) 0.067ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#4) 0.143ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#10) 0.048ms
> [2022-01-27T18:51:41.134+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#3) 0.057ms
> [2022-01-27T18:51:41.135+0000][34725.496s][debug][gc,phases ] GC(2927)
> Concurrent Roots OopStorageSet (ZWorker#14) 0.249ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#5) 4.032ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#16) 3.921ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#7) 3.888ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#3) 3.685ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#4) 3.857ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#10) 3.725ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#12) 4.064ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#6) 4.137ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#17) 3.998ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#0) 4.301ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#8) 4.335ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#14) 3.658ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#15) 3.966ms
> [2022-01-27T18:51:41.139+0000][34725.500s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#13) 4.267ms
> [2022-01-27T18:51:41.139+0000][34725.501s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#1) 4.165ms
> [2022-01-27T18:51:41.139+0000][34725.501s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#2) 4.619ms
> [2022-01-27T18:51:41.140+0000][34725.502s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#9) 5.835ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#7) 4.247ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#3) 4.243ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#6) 4.168ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#17) 4.091ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#9) 2.713ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#10) 4.187ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#0) 4.071ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#2) 3.897ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#16) 4.277ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#5) 4.319ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#4) 4.231ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#15) 3.997ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#13) 3.983ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#14) 4.049ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#1) 3.968ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#8) 4.092ms
> [2022-01-27T18:51:41.143+0000][34725.505s][debug][gc,phases ] GC(2927)
> Concurrent Roots JavaThreads (ZWorker#12) 4.155ms
> [2022-01-27T18:51:41.148+0000][34725.510s][debug][gc,phases ] GC(2927)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#11) 13.665ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#12) 28.078ms
> [2022-01-27T18:51:41.174+0000][34725.536s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#0) 30.133ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#3) 30.557ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#13) 29.600ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#5) 29.829ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#9) 30.148ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#10) 30.083ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#15) 29.707ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#7) 30.647ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#4) 29.814ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#8) 29.350ms
> [2022-01-27T18:51:41.174+0000][34725.536s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#14) 29.569ms
> [2022-01-27T18:51:41.174+0000][34725.536s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#1) 29.496ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#17) 30.227ms
> [2022-01-27T18:51:41.174+0000][34725.536s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#6) 30.641ms
> [2022-01-27T18:51:41.174+0000][34725.536s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#16) 29.984ms
> [2022-01-27T18:51:41.174+0000][34725.536s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#2) 30.087ms
> [2022-01-27T18:51:41.174+0000][34725.535s][debug][gc,phases ] GC(2927)
> Concurrent Roots CodeCache (ZWorker#11) 25.501ms
> [2022-01-27T18:51:41.319+0000][34725.681s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#9) 1.061ms
> [2022-01-27T18:51:41.319+0000][34725.681s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#6) 1.062ms
> [2022-01-27T18:51:41.319+0000][34725.681s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#15) 1.060ms
> [2022-01-27T18:51:41.319+0000][34725.681s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#16) 1.061ms
> [2022-01-27T18:51:41.319+0000][34725.681s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#3) 1.065ms
> [2022-01-27T18:51:41.319+0000][34725.681s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#5) 1.061ms
> [2022-01-27T18:51:41.320+0000][34725.681s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Flush (ZWorker#12) 1.921ms
> [2022-01-27T18:51:41.322+0000][34725.684s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#9) 1.061ms
> [2022-01-27T18:51:41.322+0000][34725.684s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#8) 1.062ms
> [2022-01-27T18:51:41.322+0000][34725.684s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#1) 1.063ms
> [2022-01-27T18:51:41.322+0000][34725.684s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#13) 1.059ms
> [2022-01-27T18:51:41.322+0000][34725.684s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#14) 1.066ms
> [2022-01-27T18:51:41.322+0000][34725.684s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#7) 1.065ms
> [2022-01-27T18:51:41.322+0000][34725.684s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#16) 1.061ms
> [2022-01-27T18:51:41.322+0000][34725.684s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#15) 1.063ms
> [2022-01-27T18:51:41.323+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#5) 1.061ms
> [2022-01-27T18:51:41.323+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#9) 1.057ms
> [2022-01-27T18:51:41.323+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Flush (ZWorker#12) 0.743ms
> [2022-01-27T18:51:41.323+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#0) 1.061ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#14) 1.057ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#8) 1.060ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#6) 1.059ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#17) 1.061ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#11) 1.063ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#13) 1.063ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#2) 1.058ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#3) 1.061ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#7) 1.060ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Flush (ZWorker#12) 0.356ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#4) 1.061ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#15) 1.059ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#10) 1.060ms
> [2022-01-27T18:51:41.324+0000][34725.685s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#16) 1.060ms
> [2022-01-27T18:51:41.324+0000][34725.686s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#1) 1.060ms
> [2022-01-27T18:51:41.324+0000][34725.686s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Flush (ZWorker#12) 0.311ms
> [2022-01-27T18:51:41.324+0000][34725.686s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#9) 1.060ms
> [2022-01-27T18:51:41.324+0000][34725.686s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#5) 1.058ms
> [2022-01-27T18:51:41.324+0000][34725.686s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Flush (ZWorker#12) 0.285ms
> [2022-01-27T18:51:41.324+0000][34725.686s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#12) 0.297ms
> [2022-01-27T18:51:41.324+0000][34725.686s][debug][gc,phases ] GC(2927)
> Concurrent Mark Try Terminate (ZWorker#12) 0.000ms
> [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*
> [2022-01-27T18:51:41.326+0000][34725.688s][info ][gc,phases ] GC(2927)
> Pause Mark End 0.070ms
> [2022-01-27T18:51:41.326+0000][34725.688s][info ][safepoint ] Safepoint
> "ZMarkEnd", Time since last: 204207403 ns, Reaching safepoint: 210401 ns,
> At safepoint: 237941 ns, Total: 448342 ns
> [2022-01-27T18:51:41.326+0000][34725.688s][info ][gc,phases ] GC(2927)
> Concurrent Mark Free 0.001ms
> [2022-01-27T18:51:41.327+0000][34725.688s][debug][gc,phases ] GC(2927)
> Concurrent References Process (ZDriver) 0.738ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#13) 3.344ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#4) 3.354ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#8) 3.366ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#0) 3.328ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#11) 3.365ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#14) 3.336ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#5) 3.362ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#1) 3.354ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#9) 3.351ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#3) 3.328ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#17) 3.333ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#10) 3.334ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#2) 3.345ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#7) 3.338ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#6) 3.329ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#15) 3.350ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#16) 3.366ms
> [2022-01-27T18:51:41.330+0000][34725.692s][debug][gc,phases ] GC(2927)
> Concurrent Weak Roots OopStorageSet (ZWorker#12) 3.370ms
> [2022-01-27T18:51:41.331+0000][34725.693s][debug][gc,phases ] GC(2927)
> Concurrent References Enqueue (ZDriver) 0.011ms
> [2022-01-27T18:51:41.331+0000][34725.693s][info ][gc,phases ] GC(2927)
> Concurrent Process Non-Strong References 5.192ms
> [2022-01-27T18:51:41.333+0000][34725.695s][info ][gc,phases ] GC(2927)
> Concurrent Reset Relocation Set 2.186ms
> [2022-01-27T18:51:41.349+0000][34725.711s][info ][gc,phases ] GC(2927)
> Concurrent Select Relocation Set 15.721ms
> [2022-01-27T18:51:41.350+0000][34725.711s][info ][gc,phases ] GC(2927)
> Pause Relocate Start 0.016ms
> [2022-01-27T18:51:41.350+0000][34725.712s][info ][safepoint ] Safepoint
> "ZRelocateStart", Time since last: 23235346 ns, Reaching safepoint: 315064
> ns, At safepoint: 290299 ns, Total: 605363 ns
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,phases ] GC(2927)
> Concurrent Relocate 19.017ms
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,marking ] GC(2927)
> Mark: 16 stripe(s), 4 proactive flush(es), 1 terminate flush(es), 0
> completion(s), 0 continuation(s)
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,marking ] GC(2927)
> Mark Stack Usage: 32M
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,metaspace] GC(2927)
> Metaspace: 169M used, 178M committed, 1184M reserved
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,ref ] GC(2927)
> Soft: 40709 encountered, 0 discovered, 0 enqueued
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,ref ] GC(2927)
> Weak: 33476 encountered, 7667 discovered, 4604 enqueued
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,ref ] GC(2927)
> Final: 415 encountered, 0 discovered, 0 enqueued
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,ref ] GC(2927)
> Phantom: 5155 encountered, 3828 discovered, 205 enqueued
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,reloc ] GC(2927)
> Small Pages: 23233 / 46466M, Empty: 17842M, Relocated: 61M, In-Place: 0
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,reloc ] GC(2927)
> Medium Pages: 161 / 5152M, Empty: 5056M, Relocated: 9M, In-Place: 0
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,reloc ] GC(2927)
> Large Pages: 0 / 0M, Empty: 0M, Relocated: 0M, In-Place: 0
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,reloc ] GC(2927)
> Forwarding Usage: 13M
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Min Capacity: 64000M(100%)
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Max Capacity: 64000M(100%)
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Soft Max Capacity: 64000M(100%)
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Mark Start Mark End Relocate Start
> Relocate End High Low
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Capacity: 64000M (100%) 64000M (100%) 64000M (100%)
> 64000M (100%) 64000M (100%) 64000M (100%)
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Free: 12382M (19%) 11392M (18%) 34172M (53%) 61184M
> (96%) 61184M (96%) 11326M (18%)
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Used: 51618M (81%) 52608M (82%) 29828M (47%) 2816M
> (4%) 52674M (82%) 2816M (4%)
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Live: - 1303M (2%) 1303M (2%) 1303M
> (2%) - -
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Allocated: - 990M (2%) 1108M (2%)
> 1195M (2%) - -
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Garbage: - 50314M (79%) 27416M (43%) 316M
> (0%) - -
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc,heap ] GC(2927)
> Reclaimed: - - 22898M (36%)
> 49997M (78%) - -
> [2022-01-27T18:51:41.369+0000][34725.731s][info ][gc ] GC(2927)
> Garbage Collection (Proactive) 51618M(81%)->2816M(4%)
> [2022-01-27T18:51:51.319+0000][34735.681s][info ][gc,start ] GC(2928)
> Garbage Collection (Allocation Rate)
> [2022-01-27T18:51:51.321+0000][34735.682s][info ][gc,phases ] GC(2928)
> Pause Mark Start 0.042ms
> [2022-01-27T18:51:51.321+0000][34735.683s][info ][safepoint ] Safepoint
> "ZMarkStart", Time since last: 9969777477 ns, Reaching safepoint: 887200
> ns, At safepoint: 523517 ns, Total: 1410717 ns
> [2022-01-27T18:51:51.334+0000][34735.696s][debug][gc,phases ] GC(2928)
> Concurrent Roots OopStorageSet (ZWorker#17) 0.542ms
> [2022-01-27T18:51:51.334+0000][34735.696s][debug][gc,phases ] GC(2928)
> Concurrent Roots OopStorageSet (ZWorker#10) 0.575ms
> [2022-01-27T18:51:51.343+0000][34735.705s][debug][gc,phases ] GC(2928)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#17) 9.161ms
> [2022-01-27T18:51:51.344+0000][34735.706s][debug][gc,phases ] GC(2928)
> Concurrent Roots ClassLoaderDataGraph (ZWorker#10) 9.817ms
> [2022-01-27T18:51:51.351+0000][34735.713s][debug][gc,phases ] GC(2928)
> Concurrent Roots JavaThreads (ZWorker#10) 7.569ms
> [2022-01-27T18:51:51.351+0000][34735.713s][debug][gc,phases ] GC(2928)
> Concurrent Roots JavaThreads (ZWorker#17) 8.243ms
> [2022-01-27T18:51:51.407+0000][34735.769s][debug][gc,phases ] GC(2928)
> Concurrent Roots CodeCache (ZWorker#17) 55.952ms
> [2022-01-27T18:51:51.407+0000][34735.769s][debug][gc,phases ] GC(2928)
> Concurrent Roots CodeCache (ZWorker#10) 55.988ms
> [2022-01-27T18:51:52.336+0000][34736.698s][debug][gc,phases ] GC(2928)
> Concurrent Mark Try Terminate (ZWorker#14) 1.064ms
> [2022-01-27T18:51:52.337+0000][34736.699s][debug][gc,phases ] GC(2928)
> Concurrent Mark Try Flush (ZWorker#12) 2.343ms
> [2022-01-27T18:51:52.342+0000][34736.703s][debug][gc,phases ] GC(2928)
> Concurrent Mark Try Flush (ZWorker#12) 0.685ms
> [2022-01-27T18:51:52.342+0000][34736.704s][debug][gc,phases ] GC(2928)
> Concurrent Mark Try Flush (ZWorker#12) 0.294ms
> [2022-01-27T18:51:52.342+0000][34736.704s][debug][gc,phases ] GC(2928)
> Concurrent Mark Try Terminate (ZWorker#12) 0.320ms
> [2022-01-27T18:51:52.342+0000][34736.704s][debug][gc,phases ] GC(2928)
> Concurrent Mark Try Terminate (ZWorker#12) 0.000ms
> [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:51:52.342+0000][34736.704s][info
> ][gc,phases ] GC(2928) Pause Mark End 0.095ms
> [2022-01-27T18:51:52.343+0000][34736.704s][info ][safepoint ] Safepoint
> "ZMarkEnd", Time since last: 1021138351 ns, Reaching safepoint: 256951 ns,
> At safepoint: 333825 ns, Total: 590776 ns
> [2022-01-27T18:51:52.343+0000][34736.704s][info ][gc,phases ] GC(2928)
> Concurrent Mark Free 0.001ms
> [2022-01-27T18:51:52.345+0000][34736.707s][debug][gc,phases ] GC(2928)
> Concurrent References Process (ZDriver) 2.019ms
> [2022-01-27T18:51:52.364+0000][34736.726s][debug][gc,phases ] GC(2928)
> Concurrent Weak Roots OopStorageSet (ZWorker#13) 19.096ms
> [2022-01-27T18:51:52.364+0000][34736.726s][debug][gc,phases ] GC(2928)
> Concurrent Weak Roots OopStorageSet (ZWorker#7) 19.068ms
> [2022-01-27T18:51:52.365+0000][34736.727s][debug][gc,phases ] GC(2928)
> Concurrent References Enqueue (ZDriver) 0.010ms
> [2022-01-27T18:51:52.365+0000][34736.727s][info ][gc,phases ] GC(2928)
> Concurrent Process Non-Strong References 22.133ms
> [2022-01-27T18:51:52.368+0000][34736.730s][info ][gc,phases ] GC(2928)
> Concurrent Reset Relocation Set 2.875ms
> [2022-01-27T18:51:52.384+0000][34736.745s][info ][gc,phases ] GC(2928)
> Concurrent Select Relocation Set 15.834ms
> [2022-01-27T18:51:52.384+0000][34736.746s][info ][gc,phases ] GC(2928)
> Pause Relocate Start 0.015ms
> [2022-01-27T18:51:52.384+0000][34736.746s][info ][safepoint ] Safepoint
> "ZRelocateStart", Time since last: 41003214 ns, Reaching safepoint: 303280
> ns, At safepoint: 155476 ns, Total: 458756 ns
> [2022-01-27T18:51:52.445+0000][34736.806s][info ][gc,phases ] GC(2928)
> Concurrent Relocate 60.419ms
> [2022-01-27T18:51:52.445+0000][34736.806s][info ][gc,marking ] GC(2928)
> Mark: 2 stripe(s), 2 proactive flush(es), 1 terminate flush(es), 0
> completion(s), 0 continuation(s)
> [2022-01-27T18:51:52.445+0000][34736.806s][info ][gc,marking ] GC(2928)
> Mark Stack Usage: 32M
> [2022-01-27T18:51:52.445+0000][34736.806s][info ][gc,metaspace] GC(2928)
> Metaspace: 169M used, 178M committed, 1184M reserved
> [2022-01-27T18:51:52.445+0000][34736.806s][info ][gc,ref ] GC(2928)
> Soft: 40719 encountered, 0 discovered, 0 enqueued
> [2022-01-27T18:51:52.445+0000][34736.806s][info ][gc,ref ] GC(2928)
> Weak: 33189 encountered, 9016 discovered, 4318 enqueued
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,ref ] GC(2928)
> Final: 795 encountered, 387 discovered, 380 enqueued
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,ref ] GC(2928)
> Phantom: 5175 encountered, 3937 discovered, 219 enqueued
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,reloc ] GC(2928)
> Small Pages: 20919 / 41838M, Empty: 15862M, Relocated: 87M, In-Place: 0
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,reloc ] GC(2928)
> Medium Pages: 130 / 4160M, Empty: 4064M, Relocated: 11M, In-Place: 0
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,reloc ] GC(2928)
> Large Pages: 20 / 128M, Empty: 128M, Relocated: 0M, In-Place: 0
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,reloc ] GC(2928)
> Forwarding Usage: 19M
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Min Capacity: 64000M(100%)
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Max Capacity: 64000M(100%)
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Soft Max Capacity: 64000M(100%)
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Mark Start Mark End Relocate Start
> Relocate End High Low
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Capacity: 64000M (100%) 64000M (100%) 64000M (100%)
> 64000M (100%) 64000M (100%) 64000M (100%)
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Free: 17874M (28%) 13228M (21%) 33154M (52%) 57394M
> (90%) 57434M (90%) 13142M (21%)
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Used: 46126M (72%) 50772M (79%) 30846M (48%) 6606M
> (10%) 50858M (79%) 6566M (10%)
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Live: - 1301M (2%) 1301M (2%) 1301M
> (2%) - -
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Allocated: - 4646M (7%) 4774M (7%)
> 5004M (8%) - -
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Garbage: - 44824M (70%) 24770M (39%) 299M
> (0%) - -
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc,heap ] GC(2928)
> Reclaimed: - - 20054M (31%)
> 44524M (70%) - -
> [2022-01-27T18:51:52.445+0000][34736.807s][info ][gc ] GC(2928)
> Garbage Collection (Allocation Rate) 46126M(72%)->6606M(10%)
> [2022-01-27T18:52:00.820+0000][34745.182s][info ][gc,start ] GC(2929)
> Garbage Collection (Allocation Rate)
> [2022-01-27T18:52:00.821+0000][34745.183s][info ][gc,phases ] GC(2929)
> Pause Mark Start 0.057ms
> [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: 1535636 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*[2022-01-27T18:52:02.774+0000][34747.136s][info
> ][gc,phases ] GC(2929) Pause Mark End 0.212ms
> [2022-01-27T18:52:02.775+0000][34747.136s][info ][safepoint ] Safepoint
> "ZMarkEnd", Time since last: 1949455739 ns, Reaching safepoint: 2536816 ns,
> At safepoint: 606241 ns, Total: 3143057 ns
> [2022-01-27T18:52:02.775+0000][34747.136s][info ][gc,phases ] GC(2929)
> Concurrent Mark Free 0.001ms
> [2022-01-27T18:52:02.778+0000][34747.139s][debug][gc,phases ] GC(2929)
> Concurrent References Process (ZDriver) 3.161ms
> [2022-01-27T18:52:02.813+0000][34747.175s][debug][gc,phases ] GC(2929)
> Concurrent Weak Roots OopStorageSet (ZWorker#4) 35.717ms
> [2022-01-27T18:52:02.814+0000][34747.176s][debug][gc,phases ] GC(2929)
> Concurrent References Enqueue (ZDriver) 0.007ms
> [2022-01-27T18:52:02.814+0000][34747.176s][info ][gc,phases ] GC(2929)
> Concurrent Process Non-Strong References 39.943ms
> [2022-01-27T18:52:02.818+0000][34747.180s][info ][gc,phases ] GC(2929)
> Concurrent Reset Relocation Set 3.587ms
> [2022-01-27T18:52:02.833+0000][34747.195s][info ][gc,phases ] GC(2929)
> Concurrent Select Relocation Set 15.208ms
> [2022-01-27T18:52:02.834+0000][34747.195s][info ][gc,phases ] GC(2929)
> Pause Relocate Start 0.017ms
> [2022-01-27T18:52:02.834+0000][34747.196s][info ][safepoint ] Safepoint
> "ZRelocateStart", Time since last: 58881245 ns, Reaching safepoint: 286775
> ns, At safepoint: 232929 ns, Total: 519704 ns
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,phases ] GC(2929)
> Concurrent Relocate 107.558ms
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,marking ] GC(2929)
> Mark: 1 stripe(s), 2 proactive flush(es), 1 terminate flush(es), 0
> completion(s), 0 continuation(s)
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,marking ] GC(2929)
> Mark Stack Usage: 32M
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,metaspace] GC(2929)
> Metaspace: 169M used, 178M committed, 1184M reserved
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,ref ] GC(2929)
> Soft: 40717 encountered, 0 discovered, 0 enqueued
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,ref ] GC(2929)
> Weak: 32517 encountered, 8597 discovered, 3652 enqueued
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,ref ] GC(2929)
> Final: 415 encountered, 6 discovered, 0 enqueued
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,ref ] GC(2929)
> Phantom: 5031 encountered, 3633 discovered, 77 enqueued
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,reloc ] GC(2929)
> Small Pages: 18075 / 36150M, Empty: 12846M, Relocated: 76M, In-Place: 0
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,reloc ] GC(2929)
> Medium Pages: 117 / 3744M, Empty: 3584M, Relocated: 10M, In-Place: 0
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,reloc ] GC(2929)
> Large Pages: 16 / 104M, Empty: 104M, Relocated: 0M, In-Place: 0
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,reloc ] GC(2929)
> Forwarding Usage: 15M
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,heap ] GC(2929)
> Min Capacity: 64000M(100%)
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,heap ] GC(2929)
> Max Capacity: 64000M(100%)
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,heap ] GC(2929)
> Soft Max Capacity: 64000M(100%)
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,heap ] GC(2929)
> Mark Start Mark End Relocate Start
> Relocate End High Low
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,heap ] GC(2929)
> Capacity: 64000M (100%) 64000M (100%) 64000M (100%)
> 64000M (100%) 64000M (100%) 64000M (100%)
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,heap ] GC(2929)
> Free: 24002M (38%) 15544M (24%) 31836M (50%) 53224M
> (83%) 53414M (83%) 15410M (24%)
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,heap ] GC(2929)
> Used: 39998M (62%) 48456M (76%) 32164M (50%) 10776M
> (17%) 48590M (76%) 10586M (17%)
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,heap ] GC(2929)
> Live: - 1283M (2%) 1283M (2%) 1283M
> (2%) - -
> [2022-01-27T18:52:02.942+0000][34747.303s][info ][gc,heap ] GC(2929)
> Allocated: - 8458M (13%) 8700M (14%)
> 9205M (14%) - -
> [2022-01-27T18:52:02.942+0000][34747.304s][info ][gc,heap ] GC(2929)
> Garbage: - 38714M (60%) 22180M (35%) 286M
> (0%) - -
> [2022-01-27T18:52:02.942+0000][34747.304s][info ][gc,heap ] GC(2929)
> Reclaimed: - - 16534M (26%)
> 38427M (60%) - -
> [2022-01-27T18:52:02.942+0000][34747.304s][info ][gc ] GC(2929)
> Garbage Collection (Allocation Rate) 39998M(62%)->10776M(17%)
>
>
> Thanks
> Sundar
>
>
> On Thu, Jan 27, 2022 at 11:00 AM Sundara Mohan M <m.sundar85 at gmail.com>
> wrote:
>
>> 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