8271931: Make AbortVMOnVMOperationTimeout more resilient to OS scheduling #5016

albertnetymk · 2021-08-05T09:47:18Z

Perform VM-op timeout also on the VM thread. If a VM-op is stuck, the existing watcher-thread based machinery will kick in and detect it.

Test: tier1

Progress

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

Issue

JDK-8271931: Make AbortVMOnVMOperationTimeout more resilient to OS scheduling

Reviewers

Aleksey Shipilev (@shipilev - Reviewer) ⚠️ Review applies to e9b2642
David Holmes (@dholmes-ora - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 5016

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

Using diff file

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

bridgekeeper · 2021-08-05T09:52:36Z

👋 Welcome back ayang! 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 · 2021-08-05T09:54:41Z

@albertnetymk 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 · 2021-08-05T09:59:40Z

Webrevs

shipilev

TBH, the decision to only check this at periodic task was to avoid excess overhead. But I don't think this concern is relevant for this patch, as it would only be entered when timeout is enabled. I do have suggestions to simplify the patch:

shipilev · 2021-08-05T10:27:14Z

src/hotspot/share/runtime/vmThread.cpp

+      jlong delay = nanos_to_millis(os::javaTimeNanos() - vm_op_start_ns);
+      if (delay > AbortVMOnVMOperationTimeoutDelay) {
+        fatal("%s VM operation took too long: completed in " JLONG_FORMAT " ms (timeout: " INTX_FORMAT " ms)",
+              _cur_vm_operation->name(), delay, AbortVMOnVMOperationTimeoutDelay);
+      }


This duplicates VMOperationTimeoutTask::task body. So I think this is better to be moved to a separate method, e.g. VMOperationTimeoutTask::check_and_fail, which we can then call from both ::task and ::disarm.

After this, we would also not need any other changes here: it would allow to check that task is NULL all the same.

Note the fatal msg is different: on VM thread we know the VM-op has completed, but on TimeoutTask the VM-op status is unknown.

How about sth like this?

bool check_timeout(jlong& delay) { delay = nanos_to_millis(os::javaTimeNanos() - _arm_time); return delay > AbortVMOnVMOperationTimeoutDelay } void disarm() { Atomic::release_store_fence(&_armed, 0); jlong delay; if (check_timeout(delay)) { fatal("%s VM operation took too long: completed in " JLONG_FORMAT " ms (timeout: " INTX_FORMAT " ms)", _cur_vm_operation->name(), delay, AbortVMOnVMOperationTimeoutDelay); } }

Huh, I missed this difference. Yeah, that goes in the right direction. Can we just pass the const char* with the format string to checking method? So we don't do the out-parameter, and the code ends up being:

bool maybe_fail_with(const char* fail_msg) { jlong delay = nanos_to_millis(os::javaTimeNanos() - _arm_time); if (delay > AbortVMOnVMOperationTimeoutDelay) { fatal(fail_msg, delay, AbortVMOnVMOperationTimeoutDelay); } } void disarm() { Atomic::release_store_fence(&_armed, 0); maybe_fail_with("VM operation took too long: completed in " JLONG_FORMAT " ms (timeout: " INTX_FORMAT " ms)"); }

I actually think having the format string and the variables in the same scope/statement is better, because one can match the format specifier with the corresponding variable easily.

I have no concerns about "duplicate" related checks here - it just isn't worth overthinking/over-engineering this IMO.

dholmes-ora

Hi Albert,

The changes look good to me.

Thanks,
David

dholmes-ora · 2021-08-06T02:11:09Z

src/hotspot/share/runtime/vmThread.cpp

+      jlong delay = nanos_to_millis(os::javaTimeNanos() - vm_op_start_ns);
+      if (delay > AbortVMOnVMOperationTimeoutDelay) {
+        fatal("%s VM operation took too long: completed in " JLONG_FORMAT " ms (timeout: " INTX_FORMAT " ms)",
+              _cur_vm_operation->name(), delay, AbortVMOnVMOperationTimeoutDelay);
+      }


I have no concerns about "duplicate" related checks here - it just isn't worth overthinking/over-engineering this IMO.

openjdk · 2021-08-06T02:11:58Z

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

8271931: Make AbortVMOnVMOperationTimeout more resilient to OS scheduling

Reviewed-by: shade, dholmes

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:

a86ac0d: 8271939: Clean up primitive raw accessors in oopDesc
b84a9c7: 8271956: AArch64: C1 build failed after JDK-8270947
38ff85c: 8271461: CompileCommand support for hidden class methods
c495ede: 8272099: mark hotspot runtime/Monitor tests which ignore external VM flags
e882087: 8271904: mark hotspot runtime/ClassFile tests which ignore external VM flags
fa36e33: 8271513: support JavaThreadIteratorWithHandle replacement by new ThreadsList::Iterator
cc61520: 8270842: G1: Only young regions need to redirty outside references in remset.
f4cf2f7: 8272095: ProblemList java/nio/channels/FileChannel/Transfer2GPlus.java on linux-aarch64
0aca4f7: 8271868: Warn user when using mac-sign option with unsigned app-image.
b6a19f1: 8271128: InlineIntrinsics support for 32-bit ARM
... and 43 more: https://git.openjdk.java.net/jdk/compare/efcdcc7fb792c77aef1da69b1fcc652b401115f7...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.

albertnetymk · 2021-08-06T11:58:04Z

we would also not need any other changes here: it would allow to check that task is NULL all the same.

Hi Aleksey, I have revised the patch to better encapsulate the timeout-check logic; still duplicated, but at least they are very close now (in the same class). Are you OK with the latest version?

shipilev

Yeah, that looks fine. I have two minor suggestions.

shipilev · 2021-08-06T15:27:07Z

src/hotspot/share/runtime/vmThread.hpp

@@ -39,15 +39,15 @@ class VMOperationTimeoutTask : public PeriodicTask {
 private:
  volatile int _armed;
  jlong _arm_time;
-
+  const char* _vm_op_name = nullptr;


Style question: are we doing these inits inline, instead of constructor?

My mistake; I will fix it.

shipilev · 2021-08-06T15:27:07Z

src/hotspot/share/runtime/vmThread.cpp

+  if (vm_op_duration > AbortVMOnVMOperationTimeoutDelay) {
+    fatal("%s VM operation took too long: completed in " JLONG_FORMAT " ms (timeout: " INTX_FORMAT " ms)",
+          _vm_op_name, vm_op_duration, AbortVMOnVMOperationTimeoutDelay);
+  }


Should we null _vm_op_name here?

It's not read by anyone from here on, so setting it to null is not needed, and a waste of the VM thread time.

My concern would be holding the pointer to something that is already unallocated long after VM op completes. I guess it is a lower risk for const char*, which is probably a reference to globally available string, but anyway. The overhead argument does not seem very relevant here, as we do other stuff in this handler when it is enabled. It is not a waste in default VM mode.

I see; cleared _vm_op_name at the end of disarm().

dholmes-ora

Hi Albert,

I preferred earlier versions that didn't shove all this extra logic into the timeout task, but it isn't worth arguing over.

Thanks,
David

dholmes-ora · 2021-08-09T05:27:04Z

src/hotspot/share/runtime/vmThread.cpp

+  // The two stores to `_armed` are counted in VM-op, but they should be
+  // insignificant compared to the actual VM-op duration.
+  jlong vm_op_duration = nanos_to_millis(os::javaTimeNanos() - _arm_time);


You could move this ahead of the store. And then you only need a small comment in arm().

You previously commented on slack: "Also disarm before getting the end time just to shorten the race with the watcher thread". I agree with that; for non-stuck VM-ops, checking timeout on VM thread is more reliable.

Yep sorry forgot about that aspect.

dholmes-ora · 2021-08-09T05:27:04Z

src/hotspot/share/runtime/vmThread.cpp

+  // Repeat the timeout-check logic on the VM thread, because
+  // VMOperationTimeoutTask might miss the arm-disarm window depending on
+  // the scheduling.
+  assert(Thread::current()->is_VM_thread(), "Check timeout on VM thread");


Seems unnecessary to assert this.

dholmes-ora · 2021-08-09T05:27:04Z

src/hotspot/share/runtime/vmThread.cpp

+    fatal("%s VM operation took too long: completed in " JLONG_FORMAT " ms (timeout: " INTX_FORMAT " ms)",
+          _vm_op_name, vm_op_duration, AbortVMOnVMOperationTimeoutDelay);
+  }
+  _vm_op_name = nullptr;


Yes clearing this is good hygiene - no dangling pointers.

dholmes-ora · 2021-08-09T12:21:09Z

src/hotspot/share/runtime/vmThread.cpp

+  // The two stores to `_armed` are counted in VM-op, but they should be
+  // insignificant compared to the actual VM-op duration.
+  jlong vm_op_duration = nanos_to_millis(os::javaTimeNanos() - _arm_time);


Yep sorry forgot about that aspect.

albertnetymk · 2021-08-09T15:19:04Z

Thanks for the review.

/integrate

openjdk · 2021-08-09T15:20:05Z

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

a86ac0d: 8271939: Clean up primitive raw accessors in oopDesc
b84a9c7: 8271956: AArch64: C1 build failed after JDK-8270947
38ff85c: 8271461: CompileCommand support for hidden class methods
c495ede: 8272099: mark hotspot runtime/Monitor tests which ignore external VM flags
e882087: 8271904: mark hotspot runtime/ClassFile tests which ignore external VM flags
fa36e33: 8271513: support JavaThreadIteratorWithHandle replacement by new ThreadsList::Iterator
cc61520: 8270842: G1: Only young regions need to redirty outside references in remset.
f4cf2f7: 8272095: ProblemList java/nio/channels/FileChannel/Transfer2GPlus.java on linux-aarch64
0aca4f7: 8271868: Warn user when using mac-sign option with unsigned app-image.
b6a19f1: 8271128: InlineIntrinsics support for 32-bit ARM
... and 43 more: https://git.openjdk.java.net/jdk/compare/efcdcc7fb792c77aef1da69b1fcc652b401115f7...master

Your commit was automatically rebased without conflicts.

openjdk · 2021-08-09T15:20:25Z

@albertnetymk Pushed as commit 2f7a469.

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

albertnetymk added 2 commits Aug 4, 2021

vmthread-timeout

02bac51

review

91127da

openjdk bot added the rfr label Aug 5, 2021

openjdk bot added the hotspot-runtime label Aug 5, 2021

shipilev suggested changes Aug 5, 2021

View changes

dholmes-ora approved these changes Aug 6, 2021

View changes

openjdk bot added the ready label Aug 6, 2021

review

efe46dc

shipilev approved these changes Aug 6, 2021

View changes

albertnetymk added 2 commits Aug 6, 2021

constructor

72c3933

disarm

e9b2642

shipilev approved these changes Aug 8, 2021

View changes

dholmes-ora approved these changes Aug 9, 2021

View changes

remove vmthread assert

18de55d

dholmes-ora approved these changes Aug 9, 2021

View changes

openjdk bot closed this Aug 9, 2021

openjdk bot added integrated and removed ready rfr labels Aug 9, 2021

albertnetymk deleted the vmthread-timeout branch Aug 9, 2021

8271931: Make AbortVMOnVMOperationTimeout more resilient to OS scheduling #5016

8271931: Make AbortVMOnVMOperationTimeout more resilient to OS scheduling #5016

albertnetymk commented Aug 5, 2021 •

edited by openjdk[bot] bot

bridgekeeper bot commented Aug 5, 2021

openjdk bot commented Aug 5, 2021

mlbridge bot commented Aug 5, 2021 •

edited

shipilev left a comment

shipilev Aug 5, 2021

shipilev Aug 5, 2021

albertnetymk Aug 5, 2021

shipilev Aug 5, 2021

albertnetymk Aug 5, 2021

dholmes-ora Aug 6, 2021

dholmes-ora left a comment

dholmes-ora Aug 6, 2021

openjdk bot commented Aug 6, 2021 •

edited

albertnetymk commented Aug 6, 2021

shipilev left a comment

shipilev Aug 6, 2021

albertnetymk Aug 6, 2021

shipilev Aug 6, 2021

albertnetymk Aug 6, 2021

shipilev Aug 7, 2021

albertnetymk Aug 7, 2021

dholmes-ora left a comment

dholmes-ora Aug 9, 2021

albertnetymk Aug 9, 2021

dholmes-ora Aug 9, 2021

dholmes-ora Aug 9, 2021

albertnetymk Aug 9, 2021

dholmes-ora Aug 9, 2021

dholmes-ora Aug 9, 2021

albertnetymk commented Aug 9, 2021

openjdk bot commented Aug 9, 2021

openjdk bot commented Aug 9, 2021

8271931: Make AbortVMOnVMOperationTimeout more resilient to OS scheduling #5016

8271931: Make AbortVMOnVMOperationTimeout more resilient to OS scheduling #5016

Conversation

albertnetymk commented Aug 5, 2021 • edited by openjdk[bot] bot

Progress

Issue

Reviewers

Reviewing

bridgekeeper bot commented Aug 5, 2021

openjdk bot commented Aug 5, 2021

mlbridge bot commented Aug 5, 2021 • edited

Webrevs

shipilev left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dholmes-ora left a comment

Choose a reason for hiding this comment

openjdk bot commented Aug 6, 2021 • edited

albertnetymk commented Aug 6, 2021

shipilev left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dholmes-ora left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

albertnetymk commented Aug 9, 2021

openjdk bot commented Aug 9, 2021

openjdk bot commented Aug 9, 2021

albertnetymk commented Aug 5, 2021 •

edited by openjdk[bot] bot

mlbridge bot commented Aug 5, 2021 •

edited

openjdk bot commented Aug 6, 2021 •

edited