8307653: Adjust delay time and gc log argument in TestAbortOnVMOperationTimeout #13878

lgxbslgx · 2023-05-09T05:34:06Z

Hi all,

This patch increases the delay time of the test TestAbortOnVMOperationTimeout
so that it can pass on the low performance devices (such as my local riscv64 dev board).

And I adjust the gc log options to get more gc log message which is useful to
inspect the issue JDK-8296819.

Thanks for the review.

Best Regards,
-- Guoxiong

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-8307653: Adjust delay time and gc log argument in TestAbortOnVMOperationTimeout

Reviewers

David Holmes (@dholmes-ora - Reviewer)
Daniel D. Daugherty (@dcubed-ojdk - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 13878

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

Using diff file

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

Webrev

Link to Webrev Comment

bridgekeeper · 2023-05-09T05:35:03Z

👋 Welcome back gli! 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 · 2023-05-09T05:36:32Z

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

hotspot-runtime

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 · 2023-05-09T05:40:25Z

Webrevs

dholmes-ora · 2023-05-09T07:32:54Z

test/hotspot/jtreg/runtime/Safepoint/TestAbortOnVMOperationTimeout.java

+        // These should definitely pass: more than 3 minutes is enough for Serial to act.
        // The values are deliberately non-round to trip off periodic task granularity.
-        for (int delay : new int[]{63423, 12388131}) {
+        for (int delay : new int[]{183423}) {
            testWith(delay, true);
        }


With only one value there is no point having the loop. Why not just replace the shorter, failing, delay with the new longer one?

With only one value there is no point having the loop

Good caught. I just obey the previous code style and forget to refactor it. Will fix it.

Why not just replace the shorter, failing, delay with the new longer one?

The longer one is useless actually. If the shorter one, 63423 previously, passed,
it means the gc time is less than 63423. Then the longer one will always pass.
And jtreg would report time out in seraval minutes normally,
so the longer time 12388131 is useless.
So I want to remove the longer one and just remain the shorter one.

dholmes-ora · 2023-05-09T22:17:50Z

test/hotspot/jtreg/runtime/Safepoint/TestAbortOnVMOperationTimeout.java

 * @summary Check abort on VM timeout is working
 * @requires vm.flagless
 * @library /test/lib
 * @modules java.base/jdk.internal.misc
 *          java.management
- * @run driver TestAbortOnVMOperationTimeout
+ * @run driver/timeout=600 TestAbortOnVMOperationTimeout


Is this change really needed? Do you see timeouts without it?

Yes, local env shows time out. The jtreg's default timeout is 480s, so I increase it to 600s.

Not quite. The default JTREG timeout is 120 seconds and the default timeoutFactor
value that we use is 4 for a total timeout value of 480 seconds. If your test runs
indicate the need for a total timeout value of 600 seconds, then you should use:

* @run driver/timeout=150

I had tried @run driver/timeout=480, but the test failed. Then I used timeout=600, the test passed. So I set it to 600.

What is your environment's timeoutFactor value?
Also, how are you running the test?

What is your environment's timeoutFactor value?

I haven't changed the default value. So it should be 4.

Also, how are you running the test?

I used the command make test Test=runtime/Safepoint/TestAbortOnVMOperationTimeout.java.

Please search your .jtr file for your run for the pattern: "test.timeout.factor"
and report the results here.

I see the text -J-Dtest.timeout.factor=4.0 in the log.

When you get a timeout with 'timeout=480', what 'elapsed time' values are in the '.jtr' file.
For my 'fastdebug' run, I see:

$ grep 'elapsed time' build/macosx-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_runtime_Safepoint_TestAbortOnVMOperationTimeout_java/runtime/Safepoint/TestAbortOnVMOperationTimeout.jtr elapsed time (seconds): 3.458 elapsed time (seconds): 3.455 elapsed time (seconds): 10.176

I can't reproduce the failed test by using @run driver/timeout=480 now. The test passes locally now with timeout=480. The elapsed time values, which belong to the current passed test, are shown below.

elapsed time (seconds): 115.718 elapsed time (seconds): 115.699 elapsed time (seconds): 555.602

I try to recall my previous steps:

The test failed locally with @run driver, without timeout option.

I changed it to @run driver/timeout=900. It passed.

I changed it to @run driver/timeout=480. It failed.

I changed it to @run driver/timeout=600. It passed.

So I push the code with @run driver/timeout=600.

Now I try @run driver/timeout=480 locally, it can't reproduce. So strange! Such intermittent fail may be related to JDK-8296819?

dcubed-ojdk · 2023-05-10T16:23:44Z

test/hotspot/jtreg/runtime/Safepoint/TestAbortOnVMOperationTimeout.java

@@ -51,11 +51,9 @@ public static void main(String[] args) throws Exception {
            return;
        }

-        // These should definitely pass: more than a minute is enough for Serial to act.
+        // These should definitely pass: more than 3 minutes is enough for Serial to act.


"These" is no longer accurate since this has been changed to test a single value.

dcubed-ojdk · 2023-05-10T16:24:28Z

test/hotspot/jtreg/runtime/Safepoint/TestAbortOnVMOperationTimeout.java

        // The values are deliberately non-round to trip off periodic task granularity.
-        for (int delay : new int[]{63423, 12388131}) {
-            testWith(delay, true);
-        }
+        testWith(183423, true);


"The values are ..." is no longer accurate since this has been changed to test a single value.

dcubed-ojdk · 2023-05-10T16:31:53Z

This patch increases the delay time of the test TestAbortOnVMOperationTimeout
so that it can pass on the low performance devices (such as my local riscv64 dev board).

The proper way to address a slow piece of hardware is to use a larger timeoutFactor value.
We typically only make small changes to the default timeout value for a test. Going from
(default) timeout=120 to timeout=180 or timeout=240 is fairly normal. I've even seen
some stress tests use timeout=300.

lgxbslgx · 2023-05-10T16:51:27Z

The proper way to address a slow piece of hardware is to use a larger timeoutFactor value.

Got it. I will remove the /timeout=600 of the test.

dcubed-ojdk · 2023-05-10T16:54:41Z

BTW, my first experiment for JDK-8296819 would
have been switching from (default) timeout=120 to timeout=180 and running that thru the stress
kit in my lab.

dholmes-ora

I am okay with these changes.

I do worry that your slow dev board may expose a lot of internal timeout issues in tests - but tests should be using values modified by the timeoutFactor to compensate for slow systems where possible. Not sure how that would apply in the current case though.

openjdk · 2023-05-11T05:00:37Z

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

8307653: Adjust delay time and gc log argument in TestAbortOnVMOperationTimeout

Reviewed-by: dholmes, dcubed

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

2bf7ac5: 8297657: name demangling intermittently fails
d20034b: 8307058: Implementation of Generational ZGC
0cbfbc4: 8307813: [JVMCI] Export markWord::lock_mask_in_place to JVMCI compilers.
ba9714d: 8307610: Linker::nativeLinker should not be restricted (mainline)
ecc1d85: 8307869: Remove unnecessary log statements from arm32 fastlocking code
08fa269: 8307349: Support xlc17 clang toolchain on AIX
8ac7186: 8305416: runtime/Thread/TestAlwaysPreTouchStacks.java failed with "Did not find expected NMT output"
984fbbb: 8307810: Consistently use LockingMode instead of UseHeavyMonitors
39f4e4d: 8307758: RISC-V: Improve bit test code introduced by JDK-8291555
3cb606e: 8306965: osThread allocation failures should not abort the VM
... and 43 more: https://git.openjdk.org/jdk/compare/d9052b946682d1c0f2629455d73fe4e6b95b29db...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.

lgxbslgx · 2023-05-11T18:20:05Z

@dholmes-ora @dcubed-ojdk Thanks for the review. Integrating.
/integrate

openjdk · 2023-05-11T18:21:39Z

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

1535863: 8307848: update for deprecated sprintf for jdk.attach
cbecf42: 8307850: update for deprecated sprintf for jdk.jdi
7fcb0fd: 8307139: Fix signed integer overflow in compiler code, part 1
5d6cce0: 8307298: JFR: Ensure jdk.jfr.internal.TypeLibrary is initialized only once
51b8f3c: 8306034: add support of virtual threads to JVMTI StopThread
489658d: 8307885: com/sun/jdi/ConnectedVMs.java fails with "Invalid debuggee exitValue: 0"
9ad38cb: 8307626: java/net/httpclient/FlowAdapter* tests should close the HttpClient instances
2bf7ac5: 8297657: name demangling intermittently fails
d20034b: 8307058: Implementation of Generational ZGC
0cbfbc4: 8307813: [JVMCI] Export markWord::lock_mask_in_place to JVMCI compilers.
... and 50 more: https://git.openjdk.org/jdk/compare/d9052b946682d1c0f2629455d73fe4e6b95b29db...master

Your commit was automatically rebased without conflicts.

openjdk · 2023-05-11T18:21:52Z

@lgxbslgx Pushed as commit 4f355c3.

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

JDK-8307653

340f642

openjdk bot changed the title ~~JDK-8307653~~ 8307653: Adjust delay time and gc log argument in TestAbortOnVMOperationTimeout May 9, 2023

openjdk bot added the rfr Pull request is ready for review label May 9, 2023

openjdk bot added the hotspot-runtime hotspot-runtime-dev@openjdk.org label May 9, 2023

dholmes-ora suggested changes May 9, 2023

View reviewed changes

Remove unnecessary loop. Add bug id. Adjust the action time out.

b9be935

dholmes-ora reviewed May 9, 2023

View reviewed changes

dcubed-ojdk suggested changes May 10, 2023

View reviewed changes

Remove timeout option. Adjust comment. Level up the log to info.

ee048c4

dholmes-ora approved these changes May 11, 2023

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label May 11, 2023

dcubed-ojdk approved these changes May 11, 2023

View reviewed changes

openjdk bot added the integrated Pull request has been integrated label May 11, 2023

openjdk bot closed this May 11, 2023

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels May 11, 2023

lgxbslgx deleted the JDK-8307653 branch May 11, 2023 18:33

8307653: Adjust delay time and gc log argument in TestAbortOnVMOperationTimeout #13878

8307653: Adjust delay time and gc log argument in TestAbortOnVMOperationTimeout #13878

Uh oh!

Conversation

lgxbslgx commented May 9, 2023 • edited by openjdk bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Progress

Issue

Reviewers

Reviewing

Webrev

Uh oh!

bridgekeeper bot commented May 9, 2023

Uh oh!

openjdk bot commented May 9, 2023

Uh oh!

mlbridge bot commented May 9, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Webrevs

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dcubed-ojdk commented May 10, 2023

Uh oh!

lgxbslgx commented May 10, 2023

Uh oh!

dcubed-ojdk commented May 10, 2023

Uh oh!

dholmes-ora left a comment

Choose a reason for hiding this comment

Uh oh!

openjdk bot commented May 11, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

lgxbslgx commented May 11, 2023

Uh oh!

openjdk bot commented May 11, 2023

Uh oh!

openjdk bot commented May 11, 2023

Uh oh!

Uh oh!

lgxbslgx commented May 9, 2023 •

edited by openjdk bot

Loading

mlbridge bot commented May 9, 2023 •

edited

Loading

openjdk bot commented May 11, 2023 •

edited

Loading