8381566: G1: Concurrent refinement pre-sweep time logged as incorrect negative value

[tabata-d]

In certain application workloads, a Young GC may occur during G1 concurrent refinement. When this happens, the pre-sweep processing time is incorrectly logged as a negative value. This is a logging-only issue at the debug level.

Cause

The pre-sweep duration is calculated using the following logic:

get_duration(State::Idle, State::SweepRT).seconds() * 1000.0

This calculation expects the current concurrent refinement cycle to have already reached the State::SweepRT state by the time the log is generated. However, if a Young GC interrupts the process before reaching SweepRT, the last recorded timestamp for State::SweepRT belongs to the previous refinement cycle.
Consequently, the code calculates the difference between the Idle state of the current cycle and the SweepRT state of the previous cycle, resulting in an incorrect negative duration.

Proposed Fix

If the process has not yet reached State::SweepRT, I propose logging the duration from Idle to the current state. While this value will be identical to the "Refinement took" time and may offer limited additional insight, it is preferable to outputting misleading negative values. Furthermore, it remains consistent with the actual time spent in the pre-sweep phase up to that point.

Alternative Considered

I considered outputting a specific message indicating that the pre-sweep did not complete (e.g., "pre-sweep not complete"). However, I decided against this to avoid duplicating large blocks of logging code, which would decrease maintainability.

Testing

• Tested on Linux x64.
• All tests in the :hotspot_gc group passed.

---

Progress

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

Issue

• JDK-8381566: G1: Concurrent refinement pre-sweep time logged as incorrect negative value (Bug - P4)

Reviewers

• Thomas Schatzl (@tschatzl - Reviewer)
• Albert Mingkun Yang (@albertnetymk - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 30551

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

Using diff file

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

Using Webrev

Link to Webrev Comment

[bridgekeeper]

👋 Welcome back dtabata! 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]

@tabata-d 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:

8381566: G1: Concurrent refinement pre-sweep time logged as incorrect negative value

Reviewed-by: tschatzl, ayang

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

• 289f3e2: 8381184: Code clean up: missing line break and print out duplication
• 261011a: 8372325: Refactor tests under jdk/java/net/httpclient to use ${test.main.class}
• 60115c0: 8380158: C2: compiler/c2/TestGVNCrash.java asserts with adr and adr_type must agree
• ... and 72 more: https://git.openjdk.org/jdk/compare/f3a1c67b1cc2db2d6b3c0519737a6519ea4fbeea...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 (@tschatzl, @albertnetymk) 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]

@tabata-d 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.

[mlbridge]

Webrevs

• 02: Full - Incremental (330b45af)
• 01: Full - Incremental (d1f7257e)
• 00: Full (53649260)

[tschatzl]

I think the fix is fine, and it is expected that in this state (before sweep-rt) all time is credited to the pre-sweep phase.

However the name of the variable is very undescriptive to me (also it indicates to me that it contains state before sweepRT only, i.e. "pre"-sweeprt state) and the "final" prefix does not evoke much.

Starting the bike-shedding engine :) I would suggest something like refinement_state_bound[ed]_by_sweeprt/state_bound[ed]_by_sweeprt instead of the existing suggestion.

[tabata-d]

Thanks for your comment.
I have fixed the name of the variable according to your suggestion.

[tschatzl]

Suggested change

	State state_bounded_by_sweeprt = (_state == State::SweepRT || _state == State::CompleteRefineWork)
	? State::SweepRT : _state;
	State state_bounded_by_sweeprt = (_state == State::SweepRT || _state == State::CompleteRefineWork)
	? State::SweepRT : _state;

Indentation.

[tabata-d]

Fixed.

[tabata-d]

/integrate

[openjdk]

@tabata-d
Your change (at version 330b45a) is now ready to be sponsored by a Committer.

[tschatzl]

Your change (at version 330b45a) is now ready to be sponsored by a Committer.

Fwiw, I almost wanted to mention it, Hotspot changes typically requires two reviewers, one capital "R" one (e.g. me) before pushes. :)

Please have some additional patience.

[tabata-d]

/reviewers 2

Thank you for letting me know!

[openjdk]

@tabata-d
The total number of required reviews for this PR (including the jcheck configuration and the last /reviewers command) is now set to 2 (with at least 1 Reviewer, 1 Author).

[tschatzl]

/sponsor

[openjdk]

Going to push as commit 31b5887.
Since your change was applied there have been 75 commits pushed to the master branch:

• 289f3e2: 8381184: Code clean up: missing line break and print out duplication
• 261011a: 8372325: Refactor tests under jdk/java/net/httpclient to use ${test.main.class}
• 60115c0: 8380158: C2: compiler/c2/TestGVNCrash.java asserts with adr and adr_type must agree
• ... and 72 more: https://git.openjdk.org/jdk/compare/f3a1c67b1cc2db2d6b3c0519737a6519ea4fbeea...master

Your commit was automatically rebased without conflicts.

[openjdk]

@tschatzl @tabata-d Pushed as commit 31b5887.

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