8279398: jdk/jfr/api/recording/time/TestTimeMultiple.java failed with "RuntimeException: getStopTime() > afterStop"

[egahlin]

Hi,

Could I have review of a fix of a regression introduced with "JDK-8268297: jdk/jfr/api/consumer/streaming/TestLatestEvent.java times out" https://bugs.openjdk.java.net/browse/JDK-8268297

Bumping the timestamp in native, if the timestamp has not changed, ensures that chunks gets a strictly increasing start time, which is needed for event streaming to order chunks chronologically.

Problem is that tests, and probably users as well, expect that the start/stop time of a recording never exceeds what a later invocation to Instant.now() returns, for example:

Recording a = new Recording();
a.start(); // first chunk begins 
a.stop(); // first chunk ends
Recording b = new Recording();
b.start(); // second chunk begins, where time stamp is taken and possibly bumped with a nanosecond.
Instant now = Instant.now();
if (now.isBefore(b.getStartTime())) {
  System.out.println("WAT");
}

This can happen on Windows where the clock has low resolution, so Recording::start() may finish execution without a clock change. The fix is to let methods that creates a new chunk spin until the clock has catched up.

To verify the fix, I modified the test jdk/jdk/jfr/api/recoding/time/TestTimeMultiple.java so it executes code similar to above 100 times per test and then ran the test 200 times without failures. Without the fix, failures were frequent.

Technically, it's not necessary for all places to use Utils::getChunkStartNanos() instead of JVM::getChunkStartNanos(), but it seemed more prudent to never use the low level function, which can in some circumstances lead to incorrect behavior.

Thanks
Erik

---

Progress

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

Issue

• JDK-8279398: jdk/jfr/api/recording/time/TestTimeMultiple.java failed with "RuntimeException: getStopTime() > afterStop"

Reviewers

• Markus Grönlund (@mgronlun - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 84

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

Using diff file

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

[bridgekeeper]

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

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

• hotspot-jfr

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

• 00: Full (33d0e801)

[openjdk]

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

8279398: jdk/jfr/api/recording/time/TestTimeMultiple.java failed with "RuntimeException: getStopTime() > afterStop"

Reviewed-by: mgronlun

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

• 928e347: 8279032: compiler/loopopts/TestSkeletonPredicateNegation.java times out with -XX:TieredStopAtLevel < 4
• 354c904: 8273452: DocTrees.getDocCommentTree should be specified as idempotent
• 06b4d49: 8278344: sun/security/pkcs12/KeytoolOpensslInteropTest.java test fails because of different openssl output
• 8f969a1: 8278930: javac tries to compile a file twice via PackageElement.getEnclosedElements
• 642ab34: 8278373: JavacTrees.searchMethod finds incorrect match
• d65c665: 8279527: Dereferencing segments backed by different scopes leads to pollution
• 967ef0c: 8278020: ~13% variation in Renaissance-Scrabble
• 7c792f2: 8279333: Some JFR tests do not accept 'GCLocker Initiated GC' as a valid GC Cause

Please see this link for an up-to-date comparison between the source branch of this pull request and the master branch.
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.

[egahlin]

/integrate

[openjdk]

Going to push as commit 40df5df.
Since your change was applied there have been 9 commits pushed to the master branch:

• ad34f03: 8279515: C1: No inlining through invokedynamic and invokestatic call sites when resolved class is not linked
• 928e347: 8279032: compiler/loopopts/TestSkeletonPredicateNegation.java times out with -XX:TieredStopAtLevel < 4
• 354c904: 8273452: DocTrees.getDocCommentTree should be specified as idempotent
• 06b4d49: 8278344: sun/security/pkcs12/KeytoolOpensslInteropTest.java test fails because of different openssl output
• 8f969a1: 8278930: javac tries to compile a file twice via PackageElement.getEnclosedElements
• 642ab34: 8278373: JavacTrees.searchMethod finds incorrect match
• d65c665: 8279527: Dereferencing segments backed by different scopes leads to pollution
• 967ef0c: 8278020: ~13% variation in Renaissance-Scrabble
• 7c792f2: 8279333: Some JFR tests do not accept 'GCLocker Initiated GC' as a valid GC Cause

Your commit was automatically rebased without conflicts.

[openjdk]

@egahlin Pushed as commit 40df5df.

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