8350314: Shenandoah: Capture thread state sync times in GC timings #23759

pengxiaolong · 2025-02-25T01:20:35Z

The change is to improve the observability of Shenandoah GC, basically there are three changes for Shenandoah GC timings in this PR:

Net GC pause timings include the time to propagate GC state to Java threads
Add new timing "Propagate GC state" in Shenandoah GC timing logs
Removal of the call of propagate_gc_state_to_all_threads from "init_update_refs", which handles gc state in handshake already.

With the change, the new GC timing log will be like:

[11.056s][info][gc,stats    ] Concurrent Reset                     89 us
[11.056s][info][gc,stats    ] Pause Init Mark (G)                 257 us
[11.056s][info][gc,stats    ] Pause Init Mark (N)                  17 us
[11.056s][info][gc,stats    ]   Update Region States                3 us
[11.056s][info][gc,stats    ]   Propagate GC state                  1 us
[11.056s][info][gc,stats    ] Concurrent Mark Roots               232 us, parallelism: 1.96x
[11.056s][info][gc,stats    ]   CMR: <total>                      456 us
[11.056s][info][gc,stats    ]   CMR: Thread Roots                 429 us, workers (us): 139, 148, 142, ---, ---, ---, 
[11.057s][info][gc,stats    ]   CMR: VM Strong Roots               11 us, workers (us):   8,   3,   0, ---, ---, ---, 
[11.057s][info][gc,stats    ]   CMR: CLDG Roots                    16 us, workers (us):  16, ---, ---, ---, ---, ---, 
[11.057s][info][gc,stats    ] Concurrent Marking                 1304 us, parallelism: 2.33x
[11.057s][info][gc,stats    ]   CM: <total>                      3043 us
[11.057s][info][gc,stats    ]   CM: Parallel Mark                3043 us, workers (us): 1023, 1017, 1003, ---, ---, ---, 
[11.057s][info][gc,stats    ]   Flush SATB                        204 us
[11.057s][info][gc,stats    ] Pause Final Mark (G)                865 us
[11.057s][info][gc,stats    ] Pause Final Mark (N)                234 us
[11.057s][info][gc,stats    ]   Finish Mark                       129 us, parallelism: 0.01x
[11.057s][info][gc,stats    ]   Propagate GC state                  2 us
[11.057s][info][gc,stats    ]   Update Region States               12 us
[11.057s][info][gc,stats    ]   Choose Collection Set              25 us
[11.057s][info][gc,stats    ]   Rebuild Free Set                   29 us
[11.057s][info][gc,stats    ] Concurrent Weak References           67 us, parallelism: 0.25x
[11.057s][info][gc,stats    ]   CWRF: <total>                      17 us
[11.057s][info][gc,stats    ]   CWRF: Weak References              17 us, workers (us):  15,   1,   0, ---, ---, ---, 
[11.057s][info][gc,stats    ] Concurrent Weak Roots               413 us
[11.057s][info][gc,stats    ]   Roots                             203 us, parallelism: 1.95x
[11.057s][info][gc,stats    ]     CWR: <total>                    396 us
[11.057s][info][gc,stats    ]     CWR: Code Cache Roots           295 us, workers (us):  90,  96, 109, ---, ---, ---, 
[11.057s][info][gc,stats    ]     CWR: VM Weak Roots              100 us, workers (us):  48,  37,  14, ---, ---, ---, 
[11.057s][info][gc,stats    ]     CWR: CLDG Roots                   2 us, workers (us): ---, ---,   2, ---, ---, ---, 
[11.058s][info][gc,stats    ]   Rendezvous                        197 us
[11.058s][info][gc,stats    ] Concurrent Cleanup                   35 us
[11.058s][info][gc,stats    ] Concurrent Class Unloading          486 us
[11.058s][info][gc,stats    ]   Unlink Stale                      398 us
[11.058s][info][gc,stats    ]     System Dictionary                 5 us
[11.058s][info][gc,stats    ]     Weak Class Links                  0 us
[11.058s][info][gc,stats    ]     Code Roots                      391 us
[11.058s][info][gc,stats    ]   Rendezvous                         69 us
[11.058s][info][gc,stats    ]   Purge Unlinked                      4 us
[11.058s][info][gc,stats    ]     Code Roots                        0 us
[11.058s][info][gc,stats    ]     CLDG                              3 us
[11.058s][info][gc,stats    ] Pause Final Roots (G)               272 us
[11.058s][info][gc,stats    ] Pause Final Roots (N)                18 us
[11.058s][info][gc,stats    ]   Propagate GC state                  3 us

Test

make test TEST=hotspot_gc_shenandoah

Progress

Change must be properly reviewed (1 review required, with at least 1 Reviewer)
Change must not contain extraneous whitespace
Commit message must refer to an issue

Issue

JDK-8350314: Shenandoah: Capture thread state sync times in GC timings (Enhancement - P4)

Reviewers

William Kemper (@earthling-amzn - Reviewer) Review applies to 2e7b2cea
Y. Srinivas Ramakrishna (@ysramakrishna - Reviewer)
Aleksey Shipilev (@shipilev - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/23759/head:pull/23759
$ git checkout pull/23759

Update a local copy of the PR:
$ git checkout pull/23759
$ git pull https://git.openjdk.org/jdk.git pull/23759/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 23759

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

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/23759.diff

Using Webrev

Link to Webrev Comment

bridgekeeper · 2025-02-25T01:21:08Z

👋 Welcome back xpeng! 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 · 2025-02-25T01:21:55Z

@pengxiaolong 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:

8350314: Shenandoah: Capture thread state sync times in GC timings

Reviewed-by: ysr, shade, wkemper

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 46 new commits pushed to the master branch:

78c18cf: 8349399: GHA: Add static-jdk build on linux-x64
e43960a: 8350616: Skip ValidateHazardPtrsClosure in non-debug builds
9ec4696: 8350313: Include timings for leaving safepoint in safepoint logging
ec6624b: 8350649: Class unloading accesses/resurrects dead Java mirror after JDK-8346567
9477c70: 8024695: new File("").exists() returns false whereas it is the current working directory
3e46480: 8350770: [BACKOUT] Protection zone for easier detection of accidental zero-nKlass use
bd112c4: 8350443: GHA: Split static-libs-bundles into a separate job
2731712: 8287749: Re-enable javadoc -serialwarn option
0f82268: 8345598: Upgrade NSS binaries for interop tests
ea2c923: 8323807: Async UL: Add a stalling mode to async UL
... and 36 more: https://git.openjdk.org/jdk/compare/65f79c145b7b1b32ed064a37ad4d2b6aca935a4c...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.

As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@earthling-amzn, @ysramakrishna, @shipilev) but any other Committer may sponsor as well.

➡️ To flag this PR as ready for integration with the above commit message, type /integrate in a new comment. (Afterwards, your sponsor types /sponsor in a new comment to perform the integration).

openjdk · 2025-02-25T01:22:39Z

@pengxiaolong The following labels will be automatically applied to this pull request:

hotspot-gc
shenandoah

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

src/hotspot/share/gc/shenandoah/shenandoahConcurrentGC.cpp

mlbridge · 2025-02-25T22:47:16Z

Webrevs

earthling-amzn

Did we really see propagate_gc_state_to_all_threads taking a long time? Or was it exiting the safepoint (i.e., after the state had been propagated) that took a long time?

src/hotspot/share/gc/shenandoah/shenandoahConcurrentGC.cpp

pengxiaolong · 2025-02-25T23:20:32Z

Did we really see propagate_gc_state_to_all_threads taking a long time? Or was it exiting the safepoint (i.e., after the state had been propagated) that took a long time?

No, we discussed it last week in Slack channel, propagate_gc_state_to_all_threads usually takes less than 10 ns for ~1k threads in our test, it is not a problem.

it was the futex call when exit the safepoint took long time, we have a fix in ShenandoahLock for mitigation since the change we made last year affects scheduler, meanwhile Aleksey is working on https://bugs.openjdk.org/browse/JDK-8350324 which should improve the time to leave safepoint which has much broader impact.

earthling-amzn

Propagating gc state for init update refs is vestigial.

src/hotspot/share/gc/shenandoah/shenandoahConcurrentGC.cpp

earthling-amzn

Thank you for the changes.

…pdate_refs

ysramakrishna · 2025-02-26T02:13:07Z

Changes are fine.

This jumped out in yr sample output:

...
[11.057s][info][gc,stats    ]   Finish Mark                       129 us, parallelism: 0.01x
...
[11.057s][info][gc,stats    ] Concurrent Weak References           67 us, parallelism: 0.25x

which seemed kinda interesting. I assume this is just a consequence of the very little work (and extremely brief time in this phase) here, and can be ignored in this sample output from likely a toy GC, or one where you may have artificially boosted the number of worker threads. Still I thought I'd ask in case you've seen this with bigger timings or more work in any of these phases with low fractional speed-ups.

ysramakrishna

LGTM

ysramakrishna · 2025-02-26T02:23:15Z

src/hotspot/share/gc/shenandoah/shenandoahHeap.cpp

  Handshake::execute(&prepare_for_update_refs);

  _update_refs_iterator.reset();
+  _gc_state_changed = false;


Sorry, what is this and why do we need it. When was it set?

In set_update_refs_in_progress() ?

May be we need a better abstraction to toggle the state_changed boolean. This seems error prone.

You are right, we don't need to set _gc_state_changed to false here, because concurrent_prepare_for_update_refs calls ShenandoahHeap::set_gc_state_concurrent to set gc state, ShenandoahHeap::set_gc_state_concurrent doesn't change _gc_state_changed to true, hence there is no need to reset it false here.

pengxiaolong · 2025-02-26T18:56:06Z

Changes are fine.

This jumped out in yr sample output:
...
[11.057s][info][gc,stats    ]   Finish Mark                       129 us, parallelism: 0.01x
...
[11.057s][info][gc,stats    ] Concurrent Weak References           67 us, parallelism: 0.25x
which seemed kinda interesting. I assume this is just a consequence of the very little work (and extremely brief time in this phase) here, and can be ignored in this sample output from likely a toy GC, or one where you may have artificially boosted the number of worker threads. Still I thought I'd ask in case you've seen this with bigger timings or more work in any of these phases with low fractional speed-ups.

I'm not sure how parallelism is calculated, but I think it is caused by the test I was running, the test is very simple and there are only small number of live objects after mark.

src/hotspot/share/gc/shenandoah/shenandoahDegeneratedGC.cpp

src/hotspot/share/gc/shenandoah/shenandoahConcurrentGC.cpp

…e timings of gc state propagation

shipilev

I am good with this, thanks. Only one minor nit remains.

src/hotspot/share/gc/shenandoah/shenandoahPhaseTimings.hpp

pengxiaolong · 2025-02-27T00:31:26Z

Thanks all for the reviews!

/integrate

openjdk · 2025-02-27T00:31:55Z

@pengxiaolong
Your change (at version caf9d4c) is now ready to be sponsored by a Committer.

ysramakrishna · 2025-02-27T02:38:52Z

I'm not sure how parallelism is calculated, but I think it is caused by the test I was running, the test is very simple and there are only small number of live objects after mark.

Yes that explains it, thanks.

(PS: Parallelism (or really parallel speed-up) is calculated as the ratio of total thread virtual time to the wall-clock (elapsed) time, IIRC. As you noted work in this specific workload is too small for the parallel task overhead, as indicated by the micro-seconds worth of time.)

shipilev · 2025-02-27T09:48:35Z

/sponsor

openjdk · 2025-02-27T09:49:30Z

Going to push as commit 01bd7e4.
Since your change was applied there have been 51 commits pushed to the master branch:

4522f12: 8349921: Crash in codeBuffer.cpp:1004: guarantee(sect->end() <= tend) failed: sanity
e4d3c97: 8350111: [PPC] AsyncGetCallTrace crashes when called while handling SIGTRAP
885338b: 8323582: C2 SuperWord AlignVector: misaligned vector memory access with unaligned native memory
bb48b73: 8350723: RISC-V: debug.cpp help() is missing riscv line for pns
b29f8b0: 8350665: SIZE_FORMAT_HEX macro undefined in gtest
78c18cf: 8349399: GHA: Add static-jdk build on linux-x64
e43960a: 8350616: Skip ValidateHazardPtrsClosure in non-debug builds
9ec4696: 8350313: Include timings for leaving safepoint in safepoint logging
ec6624b: 8350649: Class unloading accesses/resurrects dead Java mirror after JDK-8346567
9477c70: 8024695: new File("").exists() returns false whereas it is the current working directory
... and 41 more: https://git.openjdk.org/jdk/compare/65f79c145b7b1b32ed064a37ad4d2b6aca935a4c...master

Your commit was automatically rebased without conflicts.

openjdk · 2025-02-27T09:49:45Z

@shipilev @pengxiaolong Pushed as commit 01bd7e4.

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

8350314: Shenandoah: Capture thread state sync times in GC timings

358b77f

openjdk bot added hotspot-gc hotspot-gc-dev@openjdk.org shenandoah shenandoah-dev@openjdk.org labels Feb 25, 2025

shipilev reviewed Feb 25, 2025

View reviewed changes

src/hotspot/share/gc/shenandoah/shenandoahConcurrentGC.cpp Outdated Show resolved Hide resolved

Log time to propagate GC state

4940e45

pengxiaolong marked this pull request as ready for review February 25, 2025 22:42

openjdk bot added the rfr Pull request is ready for review label Feb 25, 2025

earthling-amzn suggested changes Feb 25, 2025

View reviewed changes

src/hotspot/share/gc/shenandoah/shenandoahConcurrentGC.cpp Outdated Show resolved Hide resolved

Address review comments

cad4a43

earthling-amzn suggested changes Feb 25, 2025

View reviewed changes

src/hotspot/share/gc/shenandoah/shenandoahConcurrentGC.cpp Outdated Show resolved Hide resolved

Remove propagate_gc_state_to_all_threads call from op_init_update_refs

2e7b2ce

earthling-amzn approved these changes Feb 26, 2025

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Feb 26, 2025

Set _gc_state_changed to false at the end of concurrent_prepare_for_u…

54ae1c0

…pdate_refs

openjdk bot removed the ready Pull request is ready to be integrated label Feb 26, 2025

ysramakrishna approved these changes Feb 26, 2025

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Feb 26, 2025

ysramakrishna reviewed Feb 26, 2025

View reviewed changes

Fix test failure

30647a9

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Feb 26, 2025

Remove trailing whitespace

891dd11

openjdk bot added the rfr Pull request is ready for review label Feb 26, 2025

pengxiaolong requested review from earthling-amzn, shipilev and ysramakrishna February 26, 2025 18:56

shipilev reviewed Feb 26, 2025

View reviewed changes

src/hotspot/share/gc/shenandoah/shenandoahDegeneratedGC.cpp Show resolved Hide resolved

src/hotspot/share/gc/shenandoah/shenandoahConcurrentGC.cpp Outdated Show resolved Hide resolved

Use ShenandoahTimingsTracker instead of ShenandoahGCPhase to track th…

858ebc3

…e timings of gc state propagation

shipilev approved these changes Feb 26, 2025

View reviewed changes

src/hotspot/share/gc/shenandoah/shenandoahPhaseTimings.hpp Outdated Show resolved Hide resolved

openjdk bot added the ready Pull request is ready to be integrated label Feb 26, 2025

Fix name of counter

caf9d4c

openjdk bot removed the ready Pull request is ready to be integrated label Feb 26, 2025

shipilev approved these changes Feb 26, 2025

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Feb 26, 2025

ysramakrishna approved these changes Feb 27, 2025

View reviewed changes

openjdk bot added the sponsor Pull request is ready to be sponsored label Feb 27, 2025

openjdk bot added the integrated Pull request has been integrated label Feb 27, 2025

openjdk bot closed this Feb 27, 2025

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review sponsor Pull request is ready to be sponsored labels Feb 27, 2025

8350314: Shenandoah: Capture thread state sync times in GC timings #23759

8350314: Shenandoah: Capture thread state sync times in GC timings #23759

Uh oh!

Conversation

pengxiaolong commented Feb 25, 2025 • edited by openjdk bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Test

Progress

Issue

Reviewers

Reviewing

Uh oh!

bridgekeeper bot commented Feb 25, 2025

Uh oh!

openjdk bot commented Feb 25, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

openjdk bot commented Feb 25, 2025

Uh oh!

Uh oh!

mlbridge bot commented Feb 25, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Webrevs

Uh oh!

earthling-amzn left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

pengxiaolong commented Feb 25, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

earthling-amzn left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

earthling-amzn left a comment

Choose a reason for hiding this comment

Uh oh!

ysramakrishna commented Feb 26, 2025

Uh oh!

ysramakrishna left a comment

Choose a reason for hiding this comment

Uh oh!

ysramakrishna Feb 26, 2025

Choose a reason for hiding this comment

Uh oh!

pengxiaolong Feb 26, 2025

Choose a reason for hiding this comment

Uh oh!

pengxiaolong commented Feb 26, 2025

Uh oh!

Uh oh!

Uh oh!

shipilev left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

pengxiaolong commented Feb 27, 2025

Uh oh!

openjdk bot commented Feb 27, 2025

Uh oh!

ysramakrishna commented Feb 27, 2025

Uh oh!

shipilev commented Feb 27, 2025

Uh oh!

openjdk bot commented Feb 27, 2025

Uh oh!

openjdk bot commented Feb 27, 2025

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

4 participants

pengxiaolong commented Feb 25, 2025 •

edited by openjdk bot

Loading

openjdk bot commented Feb 25, 2025 •

edited

Loading

mlbridge bot commented Feb 25, 2025 •

edited

Loading

pengxiaolong commented Feb 25, 2025 •

edited

Loading