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

Stefan Karlsson stefank at openjdk.java.net
Thu Nov 18 13:46:56 UTC 2021


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%)

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

Commit messages:
 - 8277399: ZGC: Move worker thread logging out of gc+phase=debug

Changes: https://git.openjdk.java.net/jdk/pull/6457/files
 Webrev: https://webrevs.openjdk.java.net/?repo=jdk&pr=6457&range=00
  Issue: https://bugs.openjdk.java.net/browse/JDK-8277399
  Stats: 15 lines in 1 file changed: 11 ins; 0 del; 4 mod
  Patch: https://git.openjdk.java.net/jdk/pull/6457.diff
  Fetch: git fetch https://git.openjdk.java.net/jdk pull/6457/head:pull/6457

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


More information about the hotspot-gc-dev mailing list