JDK-8227117 : normal interpreter table is not restored after single stepping with TLH
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 10,11,12,13,14
  • Priority: P2
  • Status: Closed
  • Resolution: Fixed
  • Submitted: 2019-07-02
  • Updated: 2020-06-01
  • Resolved: 2019-07-08
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 11 JDK 13 JDK 14
11.0.5Fixed 13Fixed 14 b05Fixed
Related Reports
Relates :  
JDK-8189941 - Implementation JEP 312: Thread-local handshake
Relates :  
JDK-8227338 - templateInterpreter.cpp: copy_table() needs to be safer
Description
When VM_ChangeSingleStep::doit changes interpreter table to safepoint table it will never be changed back when using handshakes. (handshakes are default on) I cannot find any code which installs the normal table. (untested)

SafepointSynchronize::end (now refactored into ::disarm_safepoint) used to always call Interpreter::ignore_safepoints();.
With handshakes it is conditioned on using global safepoint,
SafepointMechanism::uses_global_page_poll(), otherwise safepoint don't touch it.

This means that interpreter would be stuck with safepoint table forever, causing a massive slowdown.

Patch for fixing this is moving the ignore call outside of global safepoint branch, since it contains proper checks:
diff -r 9bd13d6dea77 src/hotspot/share/runtime/safepoint.cpp
--- a/src/hotspot/share/runtime/safepoint.cpp   Tue Jul 02 13:20:27 2019 -0400
+++ b/src/hotspot/share/runtime/safepoint.cpp   Tue Jul 02 22:31:36 2019 +0200
@@ -470,6 +470,7 @@
       PageArmed = false;
-      // Remove safepoint check from interpreter
-      Interpreter::ignore_safepoints();
     }

+    // Remove safepoint check from interpreter
+    Interpreter::ignore_safepoints();
+
     OrderAccess::fence(); // keep read and write of _state from floating up


Needs to be investigated and fixed if I haven't missed something.
This would affect version 10 and forward.
Comments
The bug already includes the session logs that show that the failure is no longer reproducible with the fix in place.
05-11-2019
Thanks for handling this Dan!
05-08-2019
Fix Request (11u) This resolves major problem with TLH and interpreter, possibly regressing performance. Patch applies cleanly to 11u, passes tier1. I hand-checked the jdb scenario Dan tried above: it indeed keeps safepoint table without the actual patch (but with logging), and patch fixes it.
24-07-2019
Here's a JDK11u session with the logging that shows the fix works: $ $JAVA_HOME/bin/jdb Hello Initializing jdb ... > stop in Hello.main Deferring breakpoint Hello.main. It will be set after the class is loaded. > run -showversion -Xlog:interpreter+safepoint=debug Hello run -showversion -Xlog:interpreter+safepoint=debug Hello Set uncaught java.lang.Throwable Set deferred uncaught java.lang.Throwable > VM Started: java version "11.0.4-internal" 2019-07-16 LTS Java(TM) SE Runtime Environment 18.9 (build 11.0.4-internal+0-LTS-2019-07-06-1620229.ddaugher.null) Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.4-internal+0-LTS-2019-07-06-1620229.ddaugher.null, mixed mode) Set deferred breakpoint Hello.main Breakpoint hit: "thread=main", Hello.main(), line=3 bci=0 3 System.out.println("Hello world!"); main[1] step [4.014s][debug][interpreter,safepoint] changing single step to 'on' [4.014s][debug][interpreter,safepoint] switching active_table to safept_table. [4.016s][debug][interpreter,safepoint] changing single step to 'off' [4.016s][debug][interpreter,safepoint> ] switching active_table to normal_table. Hello world! [4.019s][debug][interpreter,safepoint] changing single step to 'on' [4.019s][debug][interpreter,safepoint] switching active_table to safept_table. [4.019s][debug][interpreter,safepoint] changing single step to 'off' [4.019s][debug][interpreter,safepoint] switching active_table to normal_table. Step completed: "thread=main", Hello.main(), line=4 bci=8 4 System.out.println("Hello world!"); main[1] cont > Hello world! Hello world! Hello world! Hello world! Hello world! The application exited
06-07-2019
Here's a JDK13 session with the logging that shows the fix works: $ $JAVA_HOME/bin/jdb Hello Initializing jdb ... > stop in Hello.main Deferring breakpoint Hello.main. It will be set after the class is loaded. > run -showversion -Xlog:interpreter+safepoint=debug Hello run -showversion -Xlog:interpreter+safepoint=debug Hello Set uncaught java.lang.Throwable Set deferred uncaught java.lang.Throwable > VM Started: java version "13-internal" 2019-09-17 Java(TM) SE Runtime Environment (build 13-internal+0-2019-07-06-1430370.ddaugher.null) Java HotSpot(TM) 64-Bit Server VM (build 13-internal+0-2019-07-06-1430370.ddaugher.null, mixed mode, sharing) Set deferred breakpoint Hello.main Breakpoint hit: "thread=main", Hello.main(), line=3 bci=0 3 System.out.println("Hello world!"); main[1] step > [3.533s][debug][interpreter,safepoint] changing single step to 'on' [3.533s][debug][interpreter,safepoint] switching active_table to safept_table. [3.538s][debug][interpreter,safepoint] changing single step to 'off' [3.538s][debug][interpreter,safepoint] switching active_table to normal_table. Hello world! [3.539s][debug][interpreter,safepoint] changing single step to 'on' [3.539s][debug][interpreter,safepoint] switching active_table to safept_table. [3.539s][debug][interpreter,safepoint] changing single step to 'off' [3.539s][debug][interpreter,safepoint] switching active_table to normal_table. Step completed: "thread=main", Hello.main(), line=4 bci=8 4 System.out.println("Hello world!"); main[1] cont > Hello world! Hello world! Hello world! Hello world! Hello world! The application exited
06-07-2019
Here's a JDK11u session with the logging that shows the -XX:-ThreadLocalHandshakes option works around the bug: $ $JAVA_HOME/bin/jdb Hello Initializing jdb ... > stop in Hello.main Deferring breakpoint Hello.main. It will be set after the class is loaded. > run -showversion -Xlog:interpreter+safepoint=debug -XX:-ThreadLocalHandshakes Hello run -showversion -Xlog:interpreter+safepoint=debug -XX:-ThreadLocalHandshakes Hello [0.114s][debug][interpreter,safepoint] switching active_table to safept_table. [0.115s][debug][interpreter,safepoint] switching active_table to normal_table. [0.115s][debug][interpreter,safepoint] switching active_table to safept_table. [0.115s][debug][interpreter,safepoint] switching active_table to normal_table. Set uncaught java.lang.Throwable Set deferred uncaught java.lang.Throwable > VM Started: [0.226s][debug][interpreter,safepoint] switching active_table to safept_table. [0.226s][debug][interpreter,safepoint] switching active_table to normal_table. [0.235s][debug][interpreter,safepoint] switching active_table to safept_table. [0.235s][debug][interpreter,safepoint] switching active_table to normal_table. java version "11.0.4-internal" 2019-07-16 LTS Java(TM) SE Runtime Environment 18.9 (build 11.0.4-internal+0-LTS-2019-07-06-1620229.ddaugher.null) Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.4-internal+0-LTS-2019-07-06-1620229.ddaugher.null, mixed mode) [0.259s][debug][interpreter,safepoint] switching active_table to safept_table. [0.259s][debug][interpreter,safepoint] switching active_table to normal_table. [0.264s][debug][interpreter,safepoint] switching active_table to safept_table. [0.269s][debug][interpreter,safepoint] switching active_table to normal_table. [0.291s][debug][interpreter,safepoint] switching active_table to safept_table. [0.291s][debug][interpreter,safepoint] switching active_table to normal_table. [0.298s][debug][interpreter,safepoint] switching active_table to safept_table. Set deferred breakpoint Hello.main [0.298s][debug][interpreter,safepoint] switching active_table to normal_table. [0.300s][debug][interpreter,safepoint] switching active_table to safept_table. [0.300s][debug][interpreter,safepoint] switching active_table to normal_table. Breakpoint hit: [0.303s][debug][interpreter,safepoint] switching active_table to safept_table. [0.303s][debug][interpreter,safepoint] switching active_table to normal_table. [0.306s][debug][interpreter,safepoint] switching active_table to safept_table. [0.307s][debug][interpreter,safepoint] switching active_table to normal_table. [0.307s][debug][interpreter,safepoint] switching active_table to safept_table. [0.307s][debug][interpreter,safepoint] switching active_table to normal_table. "thread=main", Hello.main(), line=3 bci=0 3 System.out.println("Hello world!"); main[1] step [3.152s][debug][interpreter,safepoint] switching active_table to safept_table. [3.152s][debug][interpreter,safepoint] switching active_table to normal_table. [3.152s][debug][interpreter,safepoint] switching active_table to safept_table. [3.152s][debug][interpreter,safepoint] switching active_table to normal_table. [3.152s][debug][interpreter,safepoint] switching active_table to safept_table. [3.152s][debug][interpreter,safepoint] switching active_table to normal_table. [3.152s][debug][interpreter,safepoint] switching active_table to safept_table. [3.152s][debug][interpreter,safepoint] switching active_table to normal_table. [3.152s][debug][interpreter,safepoint] switching active_table to safept_table. [3.152s][debug][interpreter,safepoint] changing single step to 'on' [3.152s][debug][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. [3.152s][debug][interpreter,safepoint] single stepping is still active; ignoring ignore_safepoints() call. [3.156s][debug][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. [3.156s][debug][interpreter,safepoint] changing single step to 'off' [3.156s][debug][interpreter,safepoint] switching active_table to normal_table. Hello world! [3.159s][debug][interpreter,safepoint] switching active_table to safept_table. [3.159s][debug][interpreter,safepoint] switching active_table to normal_table. [3.161s][debug][interpreter,safepoint] switching active_table to safept_table. [3.161s][debug][interpreter,safepoint] changing single step to 'on' [3.161s][debug][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. [3.161s][debug][interpreter,safepoint] single stepping is still active; ignoring ignore_safepoints() call. [3.162s][debug][interpreter,saf Step completed: > epoint] active_table is already safept_table; notice_safepoints() call is no-op. [3.162s][debug][interpreter,safepoint] changing single step to 'off' [3.162s][debug][interpreter,safepoint] switching active_table to normal_table. [3.162s][debug][interpreter,safepoint] switching active_table to safept_table. [3.162s][debug][interpreter,safepoint]"thread=main", Hello.main(), line=4 bci=8 switching a4 System.out.println("Hello world!"); ctive_table to normal_table. main[1] [3.166s][debug][interpreter,safepoint] switching active_table to safept_table. [3.166s][debug][interpreter,safepoint] switching active_table to normal_table. [3.166s][debug][interpreter,safepoint] switching active_table to safept_table. [3.166s][debug][interpreter,safepoint] switching active_table to normal_table. [3.166s][debug][interpreter,safepoint] switching active_table to safept_table. [3.167s][debug][interpreter,safepoint] switching active_table to normal_table. main[1] The above shows that we have switch back to the normal_table. Update: Notice that because we're using global safepoints here, we do a lot of "switching active_table to safept_table." and then "switching active_table to normal_table.".
06-07-2019
Here's a JDK11u session with the logging that shows the bug reproduces there: $ $JAVA_HOME/bin/jdb Hello Initializing jdb ... > stop in Hello.main Deferring breakpoint Hello.main. It will be set after the class is loaded. > run -showversion -Xlog:interpreter+safepoint=debug Hello run -showversion -Xlog:interpreter+safepoint=debug Hello Set uncaught java.lang.Throwable Set deferred uncaught java.lang.Throwable > VM Started: java version "11.0.4-internal" 2019-07-16 LTS Java(TM) SE Runtime Environment 18.9 (build 11.0.4-internal+0-LTS-2019-07-06-1620229.ddaugher.null) Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.4-internal+0-LTS-2019-07-06-1620229.ddaugher.null, mixed mode) Set deferred breakpoint Hello.main Breakpoint hit: "thread=main", Hello.main(), line=3 bci=0 3 System.out.println("Hello world!"); main[1] step [2.458s][debug][interpreter,safepoint] changing single step to 'on' [2.458s][debug][interpreter,safepoint] switching active_table to safept_table. > [2.459s][debug][interpreter,safepoint] changing single step to 'off' Hello world! [2.464s][debug][interpreter,safepoint] changing single step to 'on' [2.464s][debug][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. [2.464s][debug][interpreter,safepoint] changing single step to 'off' Step completed: "thread=main", Hello.main(), line=4 bci=8 4 System.out.println("Hello world!"); main[1] The above shows that we are still using safept_table and did not switch back to the normal_table.
06-07-2019
Here's a JDK13 session with the logging that shows the -XX:-ThreadLocalHandshakes option works around the bug: $ $JAVA_HOME/bin/jdb Hello Initializing jdb ... > stop in Hello.main Deferring breakpoint Hello.main. It will be set after the class is loaded. > run -showversion -Xlog:interpreter+safepoint=debug -XX:-ThreadLocalHandshakes Hello run -showversion -Xlog:interpreter+safepoint=debug -XX:-ThreadLocalHandshakes Hello Java HotSpot(TM) 64-Bit Server VM warning: Option ThreadLocalHandshakes was deprecated in version 13.0 and will likely be removed in [0.140s][debug]a[int future releaserpreter,safepoint] sweitching active_table to safept_table. [0.140s][debug][. interpreter,safepoint] switching active_table to normal_table. [0.140s][debug][interpreter,safepoint] switching active_table to safept_table. [0.140s][debug][interpreter,safepoint] switching active_table to normal_table. [0.140s][debug][interpreter,safepoint] switching active_table to safept_table. [0.140s][debug][interpreter,safepoint] switching active_table to normal_table. Set uncaught java.lang.Throwable Set deferred uncaught java.lang.Throwable > VM Started: [0.387s][debug][interpreter,safepoint] switching active_table to safept_table. [0.387s][debug][interpreter,safepoint] switching active_table to normal_table. [0.389s][debug][interpreter,safepoint] switching active_table to safept_table. [0.389s][debug][interpreter,safepoint] switching active_table to normal_table. [0.389s][debug][interpreter,safepoint] switching active_table to safept_table. [0.389s][debug][interpreter,safepoint] switching active_table to normal_table. java version "13-internal" 2019-09-17 Java(TM) SE Runtime Environment (build 13-internal+0-2019-07-06-1430370.ddaugher.null) Java HotSpot(TM) 64-Bit Server VM (build 13-internal+0-2019-07-06-1430370.ddaugher.null, mixed mode, sharing) [0.438s][debug][interpreter,safepoint] switching active_table to safept_table. [0.438s][debug][interpreter,safepoint] switching active_table to normal_table. [0.467s][debug][interpreter,safepoint] switching active_table to safept_table. [0.467s][debug][interpreter,safepoint] switching active_table to normal_table. [0.485s][debug][interpreter,safepoint] switching active_table to safept_table. [0.485s][debug][interpreter,safepoint] switching active_table to normal_table. [0.520s][debug][interpreter,safepoint] switching active_table to safept_table. [0.520s][debug][interpreter,safepoint] switching active_table to normal_table. Set deferred breakpoint Hello.main [0.533s][debug][interpreter,safepoint] switching active_table to safept_table. [0.533s][debug][interpreter,safepoint] switching active_table to normal_table. Breakpoint hit: [0.565s][debug][interpreter,safepoint] switching active_table to safept_table. [0.565s][debug][interpreter,safepoint] switching active_table to normal_table. [0.578s][debug][interpreter,safepoint] switching active_table to safept_table. [0.578s][debug][interpreter,safepoint] switching active_table to normal_table. [0.578s][debug][interpreter,safepoint] switching active_table to safept_table. [0.578s][debug][interpreter,safepoint] switching active_table to normal_table. "thread=main", Hello.main(), line=3 bci=0 3 System.out.println("Hello world!"); main[1] step > [14.346s][debug][interpreter,safepoint] switching active_table to safept_table. [14.346s][debug][interpreter,safepoint] switching active_table to normal_table. [14.346s][debug][interpreter,safepoint] switching active_table to safept_table. [14.346s][debug][interpreter,safepoint] switching active_table to normal_table. [14.347s][debug][interpreter,safepoint] switching active_table to safept_table. [14.347s][debug][interpreter,safepoint] switching active_table to normal_table. [14.348s][debug][interpreter,safepoint] switching active_table to safept_table. [14.348s][debug][interpreter,safepoint] switching active_table to normal_table. [14.349s][debug][interpreter,safepoint] switching active_table to safept_table. [14.349s][debug][interpreter,safepoint] changing single step to 'on' [14.349s][debug][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. [14.349s][debug][interpreter,safepoint] single stepping is still active; ignoring ignore_safepoints() call. [14.351s][debug][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. [14.351s][debug][interpreter,safepoint] changing single step to 'off' [14.351s][debug][interpreter,safepoint] switching active_table to normal_table. Hello world! [14.352s][debug][interpreter,safepoint] switching active_table to safept_table. [14.352s][debug][interpreter,safepoint] switching active_table to normal_table. [14.352s][debug][interpreter,safepoint] switching active_table to safept_table. [14.352s][debug][interpreter,safepoint] changing single step to 'on' [14.352s][debug][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. [14.352s][debug][interpreter,safepoint] single stepping is still active; ignoring ignore_safepoints() call. [14.352s][debug][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. [14.352s][debug][interpreter,safepoint] changing single step to 'off' [14.352s][debug][interpreter,safepoint] switching active_table to normal_table. [14.353s][debug][interpreter,safepoint] switching active_table to safept_table. [14.353s][debug][interpreter,safepoint] switching active_table to normal_table. Step completed: [14.388s][debug][interpreter,safepoint] switching active_table to safept_table. [14.388s][debug][interpreter,safepoint] switching active_table to normal_table. [14.389s][debug][interpreter,safepoint] switching active_table to safept_table. [14.389s][debug][interpreter,s"thread=main", Hello.main(), line=4 bci=8 afepoint] switching active_table to normal_table. [14.389s][debug][inte4 System.out.println("Hello world!"); rpreter,safepoint] switchinmain[1] g active_table to safept_table. [14.389s][debug][interpreter,safepoint] switching active_table to normal_table. main[1] The above shows that we have switch back to the normal_table. Update: Notice that because we're using global safepoints here, we do a lot of "switching active_table to safept_table." and then "switching active_table to normal_table.".
06-07-2019
Here's a JDK13 session with the logging that shows the bug reproduces there: $ $JAVA_HOME/bin/jdb Hello Initializing jdb ... > stop in Hello.main Deferring breakpoint Hello.main. It will be set after the class is loaded. > run -showversion -Xlog:interpreter+safepoint=debug Hello run -showversion -Xlog:interpreter+safepoint=debug Hello Set uncaught java.lang.Throwable Set deferred uncaught java.lang.Throwable > VM Started: java version "13-internal" 2019-09-17 Java(TM) SE Runtime Environment (build 13-internal+0-2019-07-06-1430370.ddaugher.null) Java HotSpot(TM) 64-Bit Server VM (build 13-internal+0-2019-07-06-1430370.ddaugher.null, mixed mode, sharing) Set deferred breakpoint Hello.main Breakpoint hit: "thread=main", Hello.main(), line=3 bci=0 3 System.out.println("Hello world!"); main[1] step > [3.128s][debug][interpreter,safepoint] changing single step to 'on' [3.128s][debug][interpreter,safepoint] switching active_table to safept_table. [3.134s][debug][interpreter,safepoint] changing single step to 'off' Hello world! [3.136s][debug][interpreter,safepoint] changing single step to 'on' [3.136s][debug][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. [3.136s][debug][interpreter,safepoint] changing single step to 'off' Step completed: "thread=main", Hello.main(), line=4 bci=8 4 System.out.println("Hello world!"); The above shows that we are still using safept_table and did not switch back to the normal_table.
06-07-2019
-XX:-ThreadLocalHandshakes should be a work around on releases prior to JDK14. With JDK14, you get the following message: Java HotSpot(TM) 64-Bit Server VM warning: Ignoring option ThreadLocalHandshakes; support was removed in 14.0 With JDK13, you get the following message: $ build/linux-x86_64-normal-server-release/images/jdk/bin/java -XX:-ThreadLocalHandshakes -version Java HotSpot(TM) 64-Bit Server VM warning: Option ThreadLocalHandshakes was deprecated in version 13.0 and will likely be removed in a future release. java version "13-internal" 2019-09-17 Java(TM) SE Runtime Environment (build 13-internal+0-2019-07-02-0354418.dcubed.null) Java HotSpot(TM) 64-Bit Server VM (build 13-internal+0-2019-07-02-0354418.dcubed.null, mixed mode, sharing) so it should still work as a work around in JDK13, but I haven't test it.
03-07-2019
And here's what a session looks like with the above change made: > $ $JAVA_HOME/bin/jdb Hello > Initializing jdb ... > > stop in Hello.main > Deferring breakpoint Hello.main. > It will be set after the class is loaded. > > run -Xlog:interpreter+safepoint=debug Hello > run -Xlog:interpreter+safepoint=debug Hello > Set uncaught java.lang.Throwable > Set deferred uncaught java.lang.Throwable > > > VM Started: Set deferred breakpoint Hello.main > > Breakpoint hit: "thread=main", Hello.main(), line=3 bci=0 > 3 System.out.println("Hello world!"); > > main[1] step > > [2.727s][debug][interpreter,safepoint] changing single step to 'on' > [2.727s][debug][interpreter,safepoint] switch > Step completed: ing active_table to safept_table. > [2.729s][debug][interpreter,safepoint] changing si"thread=main", Hello.main(), line=4 bci=8 > ngle step to 4 System.out.println("Hello world!"); > > 'off'main[1] > [2.729s][debug][interpreter,safepoint] switching active_table to normal_table. > Hello world! > [2.730s][debug][interpreter,safepoint] changing single step to 'on' > [2.730s][debug][interpreter,safepoint] switching active_table to safept_table. > [2.730s][debug][interpreter,safepoint] changing single step to 'off' > [2.730s][debug][interpreter,safepoint] switching active_table to normal_table. > > main[1] cont > > Hello world! > Hello world! > Hello world! > Hello world! > Hello world! > > The application exited After the 'step' command, the active_table is changed to the normal_table.
03-07-2019
The solution for this issue is to decouple the VM_ChangeSingleStep VM-op from depending on the safepoint end mechanism to call Interpreter::ignore_safepoints(). Perhaps something like this: void VM_ChangeSingleStep::doit() { JvmtiEventControllerPrivate::set_should_post_single_step(_on); if (_on) { Interpreter::notice_safepoints(); } else { Interpreter::ignore_safepoints(); } } Update: I'm thinking about keeping the new logging to help future debugging of the interpreter table swapping. I am going to change from 'log_info()' to 'log_debug()' calls.
03-07-2019
Interpreter::notice_safepoints() is called from two places: src/hotspot/share/prims/jvmtiEventController.cpp: void VM_ChangeSingleStep::doit() { JvmtiEventControllerPrivate::set_should_post_single_step(_on); if (_on) { Interpreter::notice_safepoints(); } } and src/hotspot/share/runtime/safepoint.cpp: void SafepointSynchronize::arm_safepoint() { <snip> if (SafepointMechanism::uses_global_page_poll()) { // Make interpreter safepoint aware Interpreter::notice_safepoints(); // Make polling safepoint aware guarantee (!PageArmed, "invariant") ; PageArmed = true; os::make_polling_page_unreadable(); } } Interpreter::ignore_safepoints() is called from one place: src/hotspot/share/runtime/safepoint.cpp: void SafepointSynchronize::disarm_safepoint() { <snip> if (SafepointMechanism::uses_global_page_poll()) { guarantee (PageArmed, "invariant"); // Make polling safepoint aware os::make_polling_page_readable(); PageArmed = false; // Remove safepoint check from interpreter Interpreter::ignore_safepoints(); } The VM_ChangeSingleStep VM-op is instantiated in one place: src/hotspot/share/prims/jvmtiEventController.cpp: JvmtiEventControllerPrivate::recompute_enabled() { <snip> case JVMTI_PHASE_LIVE: { VM_ChangeSingleStep op((any_env_thread_enabled & SINGLE_STEP_BIT) != 0); VMThread::execute(&op); break; } However, the op is constructed with a parameter based on: (any_env_thread_enabled & SINGLE_STEP_BIT) != 0 so if _any_ thread has single stepping enabled, then the caller of recompute_enabled() will execute the VM_ChangeSingleStep VM-op with "_on == true" which will enable single stepping. If _no_ thread has single stepping enabled, then the caller of recompute_enabled() will execute the VM_ChangeSingleStep VM-op with "_on == false" and it relies on the pre-TLH code that disabled single stepping and the end of the safepoint. So I added more logging code to: $ hg diff src/hotspot/share/prims/jvmtiEventController.cpp diff -r 25165403c62e src/hotspot/share/prims/jvmtiEventController.cpp --- a/src/hotspot/share/prims/jvmtiEventController.cpp Wed Jul 03 16:30:19 2019 +0000 +++ b/src/hotspot/share/prims/jvmtiEventController.cpp Wed Jul 03 16:13:15 2019 -0400 @@ -340,6 +340,7 @@ // will be checked by the interpreter, and the table kept // or changed accordingly. void VM_ChangeSingleStep::doit() { + log_info(interpreter, safepoint)("changing single step to '%s'", _on ? "on" : "off"); JvmtiEventControllerPrivate::set_should_post_single_step(_on); if (_on) { Interpreter::notice_safepoints(); And now we get this logging output: > $ $JAVA_HOME/bin/jdb Hello > Initializing jdb ... > > stop in Hello.main > Deferring breakpoint Hello.main. > It will be set after the class is loaded. > > run -Xlog:interpreter+safepoint=info Hello > run -Xlog:interpreter+safepoint=info Hello > Set uncaught java.lang.Throwable > Set deferred uncaught java.lang.Throwable > > > VM Started: Set deferred breakpoint Hello.main > > Breakpoint hit: "thread=main", Hello.main(), line=3 bci=0 > 3 System.out.println("Hello world!"); > > main[1] step > > [4.909s][info][interpreter,safepoint] changing single step to 'on' > [4.909s][info][interpreter,safepoint] switching active_table to safept_table. > > [4Step completed: .911s][info][interpreter,safepoint] changing single step to 'off' > "thread=main", Hello.main(), line=4 bci=8 > Hello 4 System.out.println("Hello world!"); > > world! > [4main[1] .913s][info][interpreter,safepoint] changing single step to 'on' > [4.913s][info][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. > [4.914s][info][interpreter,safepoint] changing single step to 'off' > cont > > Hello world! > Hello world! > Hello world! > Hello world! > Hello world! > > The application exited In particular notice this bit: > main[1] step > > [4.909s][info][interpreter,safepoint] changing single step to 'on' > [4.909s][info][interpreter,safepoint] switching active_table to safept_table. > > [4Step completed: .911s][info][interpreter,safepoint] changing single step to 'off' > "thread=main", Hello.main(), line=4 bci=8 > Hello 4 System.out.println("Hello world!"); > > world! Right after the 'step' command, we change single step to 'on', do the single step (single line execution in this case), and then turn off single stepping. Or at least we try to... but it doesn't work...
03-07-2019
Added some logging to both notice_safepoints() and ignore_safepoints(): $ hg diff diff -r 25165403c62e src/hotspot/share/interpreter/templateInterpreter.cpp --- a/src/hotspot/share/interpreter/templateInterpreter.cpp Wed Jul 03 16:30:19 2019 +0000 +++ b/src/hotspot/share/interpreter/templateInterpreter.cpp Wed Jul 03 15:37:12 2019 -0400 @@ -283,9 +283,13 @@ void TemplateInterpreter::notice_safepoints() { if (!_notice_safepoints) { + log_info(interpreter, safepoint)("switching active_table to safept_table."); // switch to safepoint dispatch table _notice_safepoints = true; copy_table((address*)&_safept_table, (address*)&_active_table, sizeof(_active_table) / sizeof(address)); + } else { + log_info(interpreter, safepoint)("active_table is already safept_table; " + "notice_safepoints() call is no-op."); } } @@ -297,10 +301,17 @@ void TemplateInterpreter::ignore_safepoints() { if (_notice_safepoints) { if (!JvmtiExport::should_post_single_step()) { + log_info(interpreter, safepoint)("switching active_table to normal_table."); // switch to normal dispatch table _notice_safepoints = false; copy_table((address*)&_normal_table, (address*)&_active_table, sizeof(_active_table) / sizeof(address)); + } else { + log_info(interpreter, safepoint)("single stepping is still active; " + "ignoring ignore_safepoints() call."); } + } else { + log_info(interpreter, safepoint)("active_table is already normal_table; " + "ignore_safepoints() call is no-op."); } } Created a simple test program: $ cat Hello.java public class Hello { public static void main(String[] args) { System.out.println("Hello world!"); System.out.println("Hello world!"); System.out.println("Hello world!"); System.out.println("Hello world!"); System.out.println("Hello world!"); System.out.println("Hello world!"); } } and ran it via jdb: > $ $JAVA_HOME/bin/jdb Hello > Initializing jdb ... > > stop in Hello.main > Deferring breakpoint Hello.main. > It will be set after the class is loaded. > > run -Xlog:interpreter+safepoint=info Hello > run -Xlog:interpreter+safepoint=info Hello > Set uncaught java.lang.Throwable > Set deferred uncaught java.lang.Throwable > > > VM Started: Set deferred breakpoint Hello.main > > Breakpoint hit: "thread=main", Hello.main(), line=3 bci=0 > 3 System.out.println("Hello world!"); > > main[1] step > > [5.603s][info][interpreter,safepoint] switching active_table to safept_table. > Hello world! > [5.607s][info][inter > Step completed: preter,safepoint] active_table is already safept_tabl"thread=main", Hello.main(), line=4 bci=8 > e; notice_safe4 System.out.println("Hello world!"); > > points(main[1] ) call is no-op. > next > > [15.489s][info][interpreter,safepoint] active_tab > Step completed: le is already safept_table; notice_safepoints() call is no-op. > "thread=main", Hello.main(), line=5 bci=16 > Hello world! > [15.491s5 System.out.println("Hello world!"); > > ][infomain[1] ][interpreter,safepoint] active_table is already safept_table; notice_safepoints() call is no-op. > cont > > Hello world! > Hello world! > Hello world! > Hello world! > > The application exited First, I'm surprised that the logging output is mixed/interspersed with the jdb output, but that might be a side effect of the way jdb is capturing and/or relaying the debuggee output. Second, I'm only seeing logging messages from notice_safepoints() and nothing from ignore_safepoints(). Of course, there could be a bug in my ignore_safepoints() logging code, but... :-(
03-07-2019
Assigned to Dan, since he have knowledge about JVMTI and we discussed this last week. (I'm not 'available' right now)
02-07-2019