8338428: Add logging of final VM flags while setting properties

[lmesnik]

Some VM flags might depend on the environment and it makes sense to log final flags so it is possible to get their value when investigating failures.

I added them to VMProps, so it is always dump final flags before running tests using "-XX:+PrintFlagsFinal".

Update:
There were intermittent compilation failures when I tried to use classes from testlibrary, so I rewrtite the code without them.

---

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 2 Reviewers)

Issue

• JDK-8338428: Add logging of final VM flags while setting properties (Enhancement - P4) ⚠️ Issue is already resolved. Consider making this a "backport pull request" by setting the PR title to Backport <hash> with the hash of the original commit. See Backports.

Reviewers

• David Holmes (@dholmes-ora - Reviewer)
• Roger Riggs (@RogerRiggs - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 23054

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

Using diff file

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

Using Webrev

Link to Webrev Comment

[bridgekeeper]

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

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

8338428: Add logging of final VM flags while setting properties

Reviewed-by: dholmes, rriggs

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

• c38417a: 8348186: C1: Purge fpu_stack_size infrastructure
• f2a9d26: 8347740: java/io/File/createTempFile/SpecialTempFile.java failing
• 25fecaa: 8348039: testmake fails at IDEA after JDK-8347825
• 6a29a81: 8345750: Shenandoah: Test TestJcmdHeapDump.java#aggressive intermittent assert(gc_cause() == GCCause::_no_gc) failed: Over-writing cause
• 81912e9: 8347841: Test fixes that use deprecated time zone IDs
• 3d4afc4: 8345079: Simplify/cleanup Exception handling in RMIConnectionImpl
• a62a870: 8347995: Race condition in jdk/java/net/httpclient/offline/FixedResponseHttpClient.java
• 8e8c948: 8346866: [ASAN] memoryReserver.cpp reported applying non-zero offset to non-null pointer produced null pointer
• 1ed396b: 8346927: serviceability/dcmd/vm/[SystemMapTest.java|SystemDumpMapTest.java] fail at jmx
• 5c4a387: 8348107: test/jdk/java/net/httpclient/HttpsTunnelAuthTest.java fails intermittently
• ... and 136 more: https://git.openjdk.org/jdk/compare/10f7142dce296fedbb4d945378473d44ecde34b7...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]

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

• hotspot

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

• 05: Full - Incremental (5f87d72f)
• 04: Full - Incremental (b28439c0)
• 03: Full - Incremental (28b05e9b)
• 02: Full - Incremental (d2f3b1c2)
• 01: Full - Incremental (919c870e)
• 00: Full (6af3f1c6)

[dholmes-ora]

Does this mean that the execution of every single test must now first exec a new VM and use it to dump the flags?

And where does this output go?

[lmesnik]

Does this mean that the execution of every single test must now first exec a new VM and use it to dump the flags?

Yes, you are correct. If it looks like a problem, it could be added by requires with java property. So it could be off by default and switched on only when needed.

And where does this output go?
The jvm.flags.final.log will be located in the scratch directory near with vmprops.log.

[dholmes-ora]

Given we run many thousands of tests each day, the machine time needed to execute yet-another-vm for each test, would make this too costly. Can we not piggy-back this into the VM that does the "requires" processing?

[lmesnik]

Ough, I misread your question. I though that you are asking if it is executed even the only one single test is run.
This code is executed only one per task, not per test. So overall increase is very small, less then 0.1%

The more significant increase might be for users that run a single or very few tests with '-Xcomp" where any VM start have a significant ovehead similar to simple test execution. However, all the things are slow with the '-Xcomp'.

[openjdk]

@lmesnik Unknown command the - for a list of valid commands use /help.

[dholmes-ora]

So it is once per run of jtreg effectively? Even so while the cost to the test task is negligible the accumulated cost in machine time (which someone is paying for) is not. Everything else in VMProps queries the VM running VMProps and this should do the same. We should add a whitebox API to either retrieve, or directly dump, the final flags values.

[lmesnik]

This trick should work.
When jtreg execute GetJDKProperties VMProps to know properties to rrequires, it parse input and supress sterr. It requires too much changes to update it's output in the backward compatible way.
So the simplest fix would be to dump whol VM output with final flags into a file.
While it is possible to add WB API for this, I would prefer to don't add code if possible to avoid this.

[dholmes-ora]

Can flags supplied by a test, or the user, interfere with that invocation?

Do you really want the xml format for this file?

[lmesnik]

This invocation uses flags set to jtreg like -javaoption, -vmoption but not test-specific flags.
Unfortunately, I don't have original request about this feature. As I understand the goal is to be able to check the specific vm flags that might be host specific for failed test run, like vector instructions, memory/GC ergonomics, etc. Might be make a diff with passed local run. I think that it is going to be used very rare, just if there are any question about VM default settings.

I think it is ok to have it in xml so far. The more problem is how people aware about this information. Probably add it to https://bugs.openjdk.org/browse/JDK-8346464

[dholmes-ora]

Okay this approach seems reasonable and doesn't add a huge burden to running the tests.

Do we want to add this to all TEST.ROOT files or will hotspot and jdk suffice here?

The PR description should be updated and we probably need to expand this to other groups for review.

[lmesnik]

/cc corelibs

[openjdk]

@lmesnik
The label corelibs is not a valid label.
These labels are valid:

• graal
• serviceability
• hotspot
• hotspot-compiler
• ide-support
• kulla
• i18n
• shenandoah
• jdk
• javadoc
• security
• hotspot-runtime
• jmx
• build
• nio
• client
• core-libs
• compiler
• net
• hotspot-gc
• hotspot-jfr

[lmesnik]

/cc core-libs

[openjdk]

@lmesnik
The core-libs label was successfully added.

[RogerRiggs]

/reviewers 2 reviewer

This has a very broad impact on all tests and should have a second reviewer.

[openjdk]

@RogerRiggs
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 2 Reviewers).

[RogerRiggs]

This seems like overkill for a weak use case.

The resulting log file is in the scratch directory so it will not be retained for long.
In local builds, whoever is running the test could add the arguments.

Have there been any negative interactions with any of the test tiers due to the addition of extra logging flags?

[lmesnik]

This seems like overkill for a weak use case.

The resulting log file is in the scratch directory so it will not be retained for long. In local builds, whoever is running the test could add the arguments.

Thanks for your feedback.

Currently, typical size of artifacts for passed run take a tens of MB, so it is less then 0.5% increase. The main consumer are .jtr files.

Have there been any negative interactions with any of the test tiers due to the addition of extra logging flags?

Which negative interactions you suppose? This fix shouldn't interfere with executed tests completely.
The only restriction is that we shouldn't use added
XX:+LogVMOutput -XX:-DisplayVMOutput -XX:LogFile
in VMProps to calclulate their final values.
However, they are not used in \requires` at all.

[RogerRiggs]

I don't see when these new flags come into use. I built the PR and ran tests through make and did not see the flags (PrintFinalFlags) used when running the tests in the resulting jtr files. (I ran a subset of both jdk and hotspot/jtreg tests.)
Is there an examine test showing the flags working? Thanks

[lmesnik]

This flag is not used while tests are executed. It is used only when jtreg run VMProps, executed before all tests are run and you can find result in scratch directory.

[dholmes-ora]

Nit: the JBS title should be "Add logging of final VM flags ..." not 'if'

[RogerRiggs]

Got it, I've resolved my mis-understanding of the properties being changed to the narrow use of invoking the initial VMProps to determine the supported properties of the VM under test.

[RogerRiggs]

lgtm

[lmesnik]

/integrate

[openjdk]

@lmesnik This pull request has not yet been marked as ready for integration.

[dholmes-ora]

Still good.

[lmesnik]

/integrate

[openjdk]

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

• c38417a: 8348186: C1: Purge fpu_stack_size infrastructure
• f2a9d26: 8347740: java/io/File/createTempFile/SpecialTempFile.java failing
• 25fecaa: 8348039: testmake fails at IDEA after JDK-8347825
• 6a29a81: 8345750: Shenandoah: Test TestJcmdHeapDump.java#aggressive intermittent assert(gc_cause() == GCCause::_no_gc) failed: Over-writing cause
• 81912e9: 8347841: Test fixes that use deprecated time zone IDs
• 3d4afc4: 8345079: Simplify/cleanup Exception handling in RMIConnectionImpl
• a62a870: 8347995: Race condition in jdk/java/net/httpclient/offline/FixedResponseHttpClient.java
• 8e8c948: 8346866: [ASAN] memoryReserver.cpp reported applying non-zero offset to non-null pointer produced null pointer
• 1ed396b: 8346927: serviceability/dcmd/vm/[SystemMapTest.java|SystemDumpMapTest.java] fail at jmx
• 5c4a387: 8348107: test/jdk/java/net/httpclient/HttpsTunnelAuthTest.java fails intermittently
• ... and 136 more: https://git.openjdk.org/jdk/compare/10f7142dce296fedbb4d945378473d44ecde34b7...master

Your commit was automatically rebased without conflicts.

[openjdk]

@lmesnik Pushed as commit bbd8807.

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