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

Erik Österlund eosterlund at openjdk.java.net
Thu Nov 18 13:51:44 UTC 2021


On Thu, 18 Nov 2021 13:31:51 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%)

Looks good.

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

Marked as reviewed by eosterlund (Reviewer).

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


More information about the hotspot-gc-dev mailing list