RFR: 8277399: ZGC: Move worker thread logging out of gc+phase=debug [v2]

[Stefan Karlsson]

On Thu, 18 Nov 2021 15:18:24 GMT, Stefan Karlsson <stefank at openjdk.org> wrote:

>> When extra ZGC phase logging is turned on with -Xlog:gc+phase=debug log sub-phases, but we also log what the individual threads are doing. The thread logging is often quite excessive, and not always wanted. I propose that we move it to its own tagset -Xlog:gc+phase+thread=debug.
>> 
>> Output with -Xlog:gc,gc+phases=debug
>> 
>> Before:
>> 
>> [0,625s][info ][gc,phases] GC(1) Pause Mark Start 0,006ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots OopStorageSet (ZWorker#5) 0,000ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots OopStorageSet (ZWorker#2) 0,000ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots OopStorageSet (ZWorker#4) 0,005ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots ClassLoaderDataGraph (ZWorker#4) 0,002ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots OopStorageSet (ZWorker#7) 0,004ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots OopStorageSet (ZWorker#3) 0,000ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots OopStorageSet (ZWorker#0) 0,000ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots OopStorageSet (ZWorker#1) 0,014ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots ClassLoaderDataGraph (ZWorker#2) 0,004ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots JavaThreads (ZWorker#2) 0,004ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots JavaThreads (ZWorker#1) 0,011ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots OopStorageSet (ZWorker#6) 0,000ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots JavaThreads (ZWorker#7) 0,088ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent Roots JavaThreads (ZWorker#3) 0,120ms
>> [0,626s][debug][gc,phases] GC(1) Concurrent Roots JavaThreads (ZWorker#0) 0,150ms
>> [0,626s][debug][gc,phases] GC(1) Concurrent Roots ClassLoaderDataGraph (ZWorker#5) 0,230ms
>> [0,626s][debug][gc,phases] GC(1) Concurrent Roots JavaThreads (ZWorker#4) 1,099ms
>> [0,627s][debug][gc,phases] GC(1) Concurrent Mark Try Flush (ZWorker#2) 0,029ms
>> [0,628s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#0) 1,055ms
>> [0,628s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#3) 1,055ms
>> [0,628s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#6) 1,055ms
>> [0,629s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#2) 1,054ms
>> [0,629s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#5) 1,057ms
>> [0,629s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#1) 1,055ms
>> [0,629s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#7) 1,055ms
>> [0,629s][debug][gc,phases] GC(1) Concurrent Mark Try Flush (ZWorker#2) 0,016ms
>> [0,629s][debug][gc,phases] GC(1) Concurrent Mark Try Flush (ZWorker#4) 0,014ms
>> [0,629s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#4) 0,019ms
>> [0,629s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#4) 0,000ms
>> [0,629s][debug][gc,phases] GC(1) Concurrent Mark (ZWorker#4) 2,414ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#6) 1,054ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark (ZWorker#6) 3,173ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#0) 1,055ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark (ZWorker#0) 3,178ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#3) 1,055ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark (ZWorker#3) 3,335ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#2) 1,054ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark (ZWorker#2) 3,390ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#1) 1,056ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#7) 1,054ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark (ZWorker#7) 3,427ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark (ZWorker#1) 3,420ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark Try Terminate (ZWorker#5) 1,055ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Mark (ZWorker#5) 3,442ms
>> [0,630s][info ][gc,phases] GC(1) Concurrent Mark 4,630ms
>> [0,630s][info ][gc,phases] GC(1) Pause Mark End 0,047ms
>> [0,630s][info ][gc,phases] GC(1) Concurrent Mark Free 0,000ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent References Process (ZDriver) 0,029ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Weak Roots OopStorageSet (ZWorker#6) 0,055ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Weak Roots OopStorageSet (ZWorker#4) 0,063ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Weak Roots OopStorageSet (ZWorker#5) 0,058ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Weak Roots OopStorageSet (ZWorker#3) 0,061ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Weak Roots OopStorageSet (ZWorker#0) 0,062ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Weak Roots OopStorageSet (ZWorker#2) 0,061ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Weak Roots OopStorageSet (ZWorker#7) 0,061ms
>> [0,630s][debug][gc,phases] GC(1) Concurrent Weak Roots OopStorageSet (ZWorker#1) 0,057ms
>> [0,630s][debug][gc,phases] GC(1) ClassLoaderData 0,003ms
>> [0,630s][debug][gc,phases] GC(1) Trigger cleanups 0,000ms
>> [0,631s][debug][gc,phases] GC(1) Concurrent Classes Unlink (ZDriver) 0,413ms
>> [0,631s][debug][gc,phases] GC(1) Concurrent Classes Purge (ZDriver) 0,024ms
>> [0,631s][debug][gc,phases] GC(1) Concurrent References Enqueue (ZDriver) 0,000ms
>> [0,631s][info ][gc,phases] GC(1) Concurrent Process Non-Strong References 0,625ms
>> [0,631s][info ][gc,phases] GC(1) Concurrent Reset Relocation Set 0,001ms
>> [0,633s][info ][gc,phases] GC(1) Concurrent Select Relocation Set 1,594ms
>> [0,633s][info ][gc,phases] GC(1) Pause Relocate Start 0,021ms
>> [0,634s][info ][gc,phases] GC(1) Concurrent Relocate 1,308ms
>> [0,634s][info ][gc       ] GC(1) Garbage Collection (System.gc()) 16M(0%)->16M(0%)
>> 
>> After:
>> 
>> [0,622s][info ][gc,phases] GC(1) Pause Mark Start 0,004ms
>> [0,625s][info ][gc,phases] GC(1) Concurrent Mark 3,555ms
>> [0,625s][info ][gc,phases] GC(1) Pause Mark End 0,078ms
>> [0,625s][info ][gc,phases] GC(1) Concurrent Mark Free 0,000ms
>> [0,625s][debug][gc,phases] GC(1) Concurrent References Process 0,018ms
>> [0,626s][debug][gc,phases] GC(1) ClassLoaderData 0,003ms
>> [0,626s][debug][gc,phases] GC(1) Trigger cleanups 0,000ms
>> [0,626s][debug][gc,phases] GC(1) Concurrent Classes Unlink 0,350ms
>> [0,626s][debug][gc,phases] GC(1) Concurrent Classes Purge 0,019ms
>> [0,626s][debug][gc,phases] GC(1) Concurrent References Enqueue 0,000ms
>> [0,626s][info ][gc,phases] GC(1) Concurrent Process Non-Strong References 0,495ms
>> [0,626s][info ][gc,phases] GC(1) Concurrent Reset Relocation Set 0,001ms
>> [0,629s][info ][gc,phases] GC(1) Concurrent Select Relocation Set 1,997ms
>> [0,629s][info ][gc,phases] GC(1) Pause Relocate Start 0,029ms
>> [0,631s][info ][gc,phases] GC(1) Concurrent Relocate 1,525ms
>> [0,631s][info ][gc       ] GC(1) Garbage Collection (System.gc()) 16M(0%)->14M(0%)
>
> Stefan Karlsson has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Review Per

Thanks for reviewing!

-------------

PR: https://git.openjdk.java.net/jdk/pull/6457