Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed

Conversation

stefank
Copy link
Member

@stefank stefank commented Nov 18, 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%)

Progress

  • Change must not contain extraneous whitespace
  • Commit message must refer to an issue
  • Change must be properly reviewed

Issue

  • JDK-8277399: ZGC: Move worker thread logging out of gc+phase=debug

Reviewers

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/6457/head:pull/6457
$ git checkout pull/6457

Update a local copy of the PR:
$ git checkout pull/6457
$ git pull https://git.openjdk.java.net/jdk pull/6457/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 6457

View PR using the GUI difftool:
$ git pr show -t 6457

Using diff file

Download this PR as a diff file:
https://git.openjdk.java.net/jdk/pull/6457.diff

@bridgekeeper
Copy link

@bridgekeeper bridgekeeper bot commented Nov 18, 2021

👋 Welcome back stefank! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

@openjdk openjdk bot added the rfr label Nov 18, 2021
@openjdk
Copy link

@openjdk openjdk bot commented Nov 18, 2021

@stefank The following label will be automatically applied to this pull request:

  • hotspot-gc

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

@openjdk openjdk bot added the hotspot-gc label Nov 18, 2021
@mlbridge
Copy link

@mlbridge mlbridge bot commented Nov 18, 2021

Webrevs

fisk
fisk approved these changes Nov 18, 2021
Copy link
Contributor

@fisk fisk left a comment

Looks good.

@openjdk
Copy link

@openjdk openjdk bot commented Nov 18, 2021

@stefank This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

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

Reviewed-by: eosterlund, pliden

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 41 new commits pushed to the master branch:

  • 5d249c4: 8275071: [macos] A11y cursor gets stuck when combobox is closed
  • 354a34e: 8277336: Improve CollectedHeap::safepoint_workers comments
  • 276bfcd: 8277407: javax/swing/plaf/synth/SynthButtonUI/6276188/bug6276188.java fails to compile after JDK-8276058
  • d93b238: 8277180: Intrinsify recursive ObjectMonitor locking for C2 x64 and A64
  • 00c388b: 8259643: ZGC can return metaspace OOM prematurely
  • a44b45f: 4337793: Mark non-serializable fields of java.security.cert.Certificate and CertPath
  • b3a62b4: 8276795: Deprecate seldom used CDS flags
  • 38345bd: 8277137: Set OnSpinWaitInst/OnSpinWaitInstCount defaults to "isb"/1 for Arm Neoverse N1
  • 2c06bca: 8266368: Inaccurate after_unwind hook in C2 exception handler
  • 77cc508: 8277215: Remove redundancy in ReferenceProcessor constructor args
  • ... and 31 more: https://git.openjdk.java.net/jdk/compare/9a9a157a7d45cbfb016d4427931e1d5345210f7a...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

@openjdk openjdk bot added the ready label Nov 18, 2021
pliden
pliden approved these changes Nov 18, 2021
Copy link
Contributor

@pliden pliden left a comment

Looks good. But may I suggest that we use gc+phases=trace instead of gc+phases+thread=debug.

@stefank
Copy link
Member Author

@stefank stefank commented Nov 18, 2021

Updated with Per's suggestion. Thanks!

fisk
fisk approved these changes Nov 18, 2021
pliden
pliden approved these changes Nov 18, 2021
@stefank
Copy link
Member Author

@stefank stefank commented Nov 24, 2021

Thanks for reviewing!
/integrate

@openjdk
Copy link

@openjdk openjdk bot commented Nov 24, 2021

Going to push as commit 6d73460.
Since your change was applied there have been 112 commits pushed to the master branch:

  • 712b875: 8277397: ZGC: Add JFR event for temporary latency measurements
  • 7b2d823: 8277503: compiler/onSpinWait/TestOnSpinWaitAArch64DefaultFlags.java failed with "OnSpinWaitInst with the expected value 'isb' not found."
  • 7cb56a2: 8265796: vmTestbase/nsk/jdi/ObjectReference/referringObjects/referringObjects002/referringObjects002.java fails when running with JEP 416
  • 24e586a: 8276764: Enable deterministic file content ordering for Jar and Jmod
  • ea85e01: 8271623: Omit enclosing instance fields from inner classes that don't use it
  • 0320672: 8277451: java.lang.reflect.Field::set on static field with invalid argument type should throw IAE
  • e8acac2: 8277350: runtime/jni/checked/TestPrimitiveArrayCriticalWithBadParam.java times out
  • 8a44e09: 8268725: jshell does not support the --enable-native-access option
  • 7b67a49: 8261847: performance of java.lang.Record::toString should be improved
  • 38802ad: 8254108: ciReplay: Support incremental inlining
  • ... and 102 more: https://git.openjdk.java.net/jdk/compare/9a9a157a7d45cbfb016d4427931e1d5345210f7a...master

Your commit was automatically rebased without conflicts.

@openjdk openjdk bot closed this Nov 24, 2021
@openjdk openjdk bot added integrated and removed ready rfr labels Nov 24, 2021
@openjdk
Copy link

@openjdk openjdk bot commented Nov 24, 2021

@stefank Pushed as commit 6d73460.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

@stefank stefank deleted the 8277399_worker_thread_phase_logging branch Jan 12, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
hotspot-gc integrated
3 participants