Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8277399

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

    XMLWordPrintable

Details

    • Enhancement
    • Resolution: Fixed
    • P4
    • 18
    • 18
    • hotspot
    • gc
    • b26

    Description

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

      Attachments

        Issue Links

          Activity

            People

              stefank Stefan Karlsson
              stefank Stefan Karlsson
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: