CODETOOLS-7902936: Stray output in forked VM breaks external version parsing #41

retronym · 2021-05-21T02:27:09Z

Recover from stray output before the XML prelude
- Report the output in the exception otherwise
- Silence VM warnings in PrintPropertiesMain when JEP-158 (-Xlog:) is available (JRE 9+)

Progress

Change must not contain extraneous whitespace
Change must be properly reviewed

Issue

CODETOOLS-7902936: Stray output in forked VM breaks external version parsing

Reviewers

Aleksey Shipilev (@shipilev - Committer) ⚠️ Review applies to 436ff1d

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 41

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

Using diff file

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

On an XML parse error, try again after stripping the prefix up to the XML prelude. Failing that, include the process output in the thrown exception to help the user diagnose the root cause.

bridgekeeper · 2021-05-21T02:27:33Z

👋 Welcome back jzaugg! 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.

mlbridge · 2021-05-21T02:31:04Z

Webrevs

retronym · 2021-05-21T02:32:10Z

This code path is only exercised when specifying an alternative -jvm, which doesn't appear to be done in the JMH test suite, presumably because of the hassle of requiring multiple JVMs.

I manually tested the change by:

Running just the diagnostic on a server that gives the VM warnings about duplicate cpusets. The error message included the VM warning.
JMH worked again on that machine with the commit that adds -Xlog:all=error
Locally, I added System.out.println("VM OUTPUT") to PrintPropertiesMain and tested that the recovery logic worked.

shipilev

I see little sense in trying to recover here. The stray VM output can come in the middle of that XML dump too. I would prefer to cover the "hard to debug" part only: dump the proper diagnostics and then fail hard. We can probably print the helpful message how to shun the VM warnings, if user is so inclined?

jmh-core/src/main/java/org/openjdk/jmh/runner/Runner.java

jmh-core/src/main/java/org/openjdk/jmh/util/Utils.java

retronym · 2021-05-22T01:54:46Z

I would prefer to cover the "hard to debug" part only: dump the proper diagnostics and then fail hard

No worries, I thought I'd throw the whole gamut in here and let you decide what to include.

We can probably print the helpful message how to shun the VM warnings, if user is so inclined?

What advice could we give? The use can't currently add JVM options to the PrintPropertiesMain forked JVM.

FWIW, I haven't yet found a way to reconfigure the Linux system to avoid my particular VM warning. Not necessarily because its hard to fix, but more because I'm clueless about this part of Linux. At some point an OS upgrade would make sense but that could introduce a discontinuity into our historical benchmark results.

The other options I haven't explored, but seem easy enough to implement are:

use a temporary file to transfer the XML. The parent process could create the file and pass its name as an argument to PrintPropertiesMain.
use BinaryLinkServer to allow the the properties to be pushed back over a socket.

Just throw a more useful exception and leave the user to resolve the root cause.

shipilev · 2021-05-25T16:47:53Z

What advice could we give? The use can't currently add JVM options to the PrintPropertiesMain forked JVM.

Argh. I thought we can ask user to provide -Xlog shun manually.

use a temporary file to transfer the XML. The parent process could create the file and pass its name as an argument to PrintPropertiesMain.

Yes, temp file would be cleanest option here. Call FileUtils.tempFile("properties") in host VM, pass the name of that file as the first argument to PrintPropertiesMain, let it write there, read the file back. This whole stdout mess is why JMH eventually moved to BinaryLinkServer/Client -- relying on standard streams to be pristine is wishful thinking :( But using the binary link here would be overkill.

retronym · 2021-05-26T04:10:07Z

Yes, temp file would be cleanest option here

Done. That enabled a small cleanup to implement this in terms of tryWith.

I've also added a test that exercises PrintPropertiesMain by passing -jvm current_jdk/bin/./java. That looks like a different VM to Runner without actually needing a second JVM around to run tests.

shipilev

This is good. Rename the test file, and we are good to go.

shipilev · 2021-05-26T06:58:28Z

jmh-core-it/src/test/java/org/openjdk/jmh/it/jvmoption/JvmOption.java

+@Warmup(iterations = 1, time = 100, timeUnit = TimeUnit.MILLISECONDS)
+@Fork(1)
+@State(Scope.Thread)
+public class JvmOption {


This should be JvmOptionTest to match the naming convention for the tests.

openjdk · 2021-05-26T07:00:34Z

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

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

7902936: Stray output in forked VM breaks external version parsing

Reviewed-by: shade

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 no new commits pushed to the master branch. If another commit should be pushed before you perform the /integrate command, your PR will be automatically rebased. If you prefer to avoid any potential 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 (@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).

retronym · 2021-05-26T08:00:19Z

/integrate

openjdk · 2021-05-26T08:01:12Z

@retronym
Your change (at version 805ebf4) is now ready to be sponsored by a Committer.

shipilev · 2021-05-26T08:04:56Z

/sponsor

retronym · 2021-05-26T08:05:40Z

Just pushed an extra commit to remove an unused import I introduced, hope I haven't provoked a race condition in the bot!

openjdk · 2021-05-26T08:06:06Z

@shipilev The PR has been updated since the change author (@retronym) issued the integrate command - the author must perform this command again.

retronym · 2021-05-26T08:06:15Z

Clever bot!

retronym · 2021-05-26T08:06:25Z

/integrate

openjdk · 2021-05-26T08:06:55Z

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

shipilev · 2021-05-26T08:07:37Z

Ok, now waiting for GHAs to complete again.

shipilev · 2021-05-26T09:22:42Z

/sponsor

openjdk · 2021-05-26T09:23:55Z

@shipilev @retronym Pushed as commit 4c34b33.

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

retronym added 2 commits May 21, 2021 12:16

Recover or report stray VM output from PrintPropertiesMain

7728a1e

On an XML parse error, try again after stripping the prefix up to the XML prelude. Failing that, include the process output in the thrown exception to help the user diagnose the root cause.

Disable VM warnings polluting XML on stdout

ee68f96

openjdk bot added the rfr Pull request is ready for review label May 21, 2021

shipilev requested changes May 21, 2021

View reviewed changes

jmh-core/src/main/java/org/openjdk/jmh/runner/Runner.java Outdated Show resolved Hide resolved

jmh-core/src/main/java/org/openjdk/jmh/util/Utils.java Outdated Show resolved Hide resolved

jmh-core/src/main/java/org/openjdk/jmh/util/Utils.java Outdated Show resolved Hide resolved

Revert prevention/recovery measures for stray VM output

7604256

Just throw a more useful exception and leave the user to resolve the root cause.

Use a temporary file to read output of PrintPropertiesMain

436ff1d

shipilev changed the title ~~CODETOOLS-7902936 Stray VM warnings in forked PrintPropertiesMain lead to hard to debug XML parse exception~~ CODETOOLS-7902936: Stray output in forked VM breaks external version parsing May 26, 2021

shipilev approved these changes May 26, 2021

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label May 26, 2021

Rename test to follow naming convention

805ebf4

openjdk bot added the sponsor Pull request is ready to be sponsored label May 26, 2021

Remove unused import

a929dbd

openjdk bot removed the sponsor Pull request is ready to be sponsored label May 26, 2021

openjdk bot added the sponsor Pull request is ready to be sponsored label May 26, 2021

openjdk bot closed this May 26, 2021

openjdk bot added integrated Pull request has been integrated and removed sponsor Pull request is ready to be sponsored ready Pull request is ready to be integrated rfr Pull request is ready for review labels May 26, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CODETOOLS-7902936: Stray output in forked VM breaks external version parsing #41

CODETOOLS-7902936: Stray output in forked VM breaks external version parsing #41

retronym commented May 21, 2021 •

edited by openjdk bot

Loading

bridgekeeper bot commented May 21, 2021

mlbridge bot commented May 21, 2021 •

edited

Loading

retronym commented May 21, 2021

shipilev left a comment •

edited

Loading

retronym commented May 22, 2021 •

edited

Loading

shipilev commented May 25, 2021 •

edited

Loading

retronym commented May 26, 2021

shipilev left a comment

shipilev May 26, 2021

openjdk bot commented May 26, 2021 •

edited

Loading

retronym commented May 26, 2021

openjdk bot commented May 26, 2021

shipilev commented May 26, 2021

retronym commented May 26, 2021

openjdk bot commented May 26, 2021

retronym commented May 26, 2021

retronym commented May 26, 2021

openjdk bot commented May 26, 2021

shipilev commented May 26, 2021

shipilev commented May 26, 2021

openjdk bot commented May 26, 2021

CODETOOLS-7902936: Stray output in forked VM breaks external version parsing #41

CODETOOLS-7902936: Stray output in forked VM breaks external version parsing #41

Conversation

retronym commented May 21, 2021 • edited by openjdk bot Loading

Progress

Issue

Reviewers

Reviewing

bridgekeeper bot commented May 21, 2021

mlbridge bot commented May 21, 2021 • edited Loading

Webrevs

retronym commented May 21, 2021

shipilev left a comment • edited Loading

Choose a reason for hiding this comment

retronym commented May 22, 2021 • edited Loading

shipilev commented May 25, 2021 • edited Loading

retronym commented May 26, 2021

shipilev left a comment

Choose a reason for hiding this comment

shipilev May 26, 2021

Choose a reason for hiding this comment

openjdk bot commented May 26, 2021 • edited Loading

retronym commented May 26, 2021

openjdk bot commented May 26, 2021

shipilev commented May 26, 2021

retronym commented May 26, 2021

openjdk bot commented May 26, 2021

retronym commented May 26, 2021

retronym commented May 26, 2021

openjdk bot commented May 26, 2021

shipilev commented May 26, 2021

shipilev commented May 26, 2021

openjdk bot commented May 26, 2021

retronym commented May 21, 2021 •

edited by openjdk bot

Loading

mlbridge bot commented May 21, 2021 •

edited

Loading

shipilev left a comment •

edited

Loading

retronym commented May 22, 2021 •

edited

Loading

shipilev commented May 25, 2021 •

edited

Loading

openjdk bot commented May 26, 2021 •

edited

Loading