JDK-8340698 : JVMTI FRAME_POP event is sometimes missed if NotifyFramePop is called as a method is returning
  • Type: Bug
  • Component: hotspot
  • Sub-Component: jvmti
  • Affected Version: 24
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2024-09-23
  • Updated: 2024-10-18
  • Resolved: 2024-10-18
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 24
24 masterFixed
Related Reports
Relates :  
Relates :  
Relates :  
Description
There is a bug in NotifyFramePop that causes it to miss the FRAME_POP event if the NotifyFramePop is done as the frame is being returned from. It appears that if you call SuspendThread at just the right time during the method return, the thread will be suspended before the frame is popped, but after the check to see if a FRAME_POP event should be generated. When this happens, it also appears that the NotifyFramePop is still put in place, and stays in place after the frame has been popped. It will then trigger a FRAME_POP even the next time the thread returns from that same frame depth, even though it is returning from a totally different method than the one that was current want NotifyFramePop was called.

I’ve written a test that demonstrates this behavior. The main thread of the test (the one that NotifyFramePop is called on) does the following

    for (int i = 0; i < 1000*1000; i++) {
        foo();
        bar();
    }

    private static int fetchInt() {
        return 13;
    }

    private static int foo() {
        return fetchInt();
    }

    private static int bar() {
        return fetchInt();
    }


There is another thread that continually does a NotifyFramePop on the above thread. It calls SuspendThread before the NotifyFramePop and ResumeThread after. It waits for the FRAME_POP event before doing the next NotifyFramePop. The FRAME_POP is always delivered, but often for the wrong method. For example, in the test log I see:

  NotifyFramePop called for method bar()I
  FRAME_POP event from method: LNotifyFramePopStressTest; foo()I

When calling NotifyFramePop, the test uses GetFrameLocation to get the name of the method that is currently at the top of the stack. When the FRAME_POP event arrives it should be the same method name, but often it is not.

Note it is important that the methods do very little in order to make it more likely that SuspendThread will be called at just the right time during method return to trigger the issue. It actually triggers a fairly high percent of the time in the above example. Larger method are less likely to see this issue.

Comments
Changeset: 85911094 Branch: master Author: Serguei Spitsyn <sspitsyn@openjdk.org> Date: 2024-10-18 19:34:17 +0000 URL: https://git.openjdk.org/jdk/commit/8591109419efc8f71544a98bdb04a48cb1afc47e
18-10-2024

A pull request was submitted for review. Branch: master URL: https://git.openjdk.org/jdk/pull/21468 Date: 2024-10-11 08:39:42 +0000
11-10-2024

The root cause of this issue is in the JRT_BLOCK below: JRT_BLOCK post_method_exit_inner(thread, mh, state, exception_exit, current_frame, value); JRT_BLOCK_END The JRT_BLOCK has ThreadInVMfromJava defined which checks for a safepoint + suspend point: #define JRT_BLOCK \ { \ assert(current == JavaThread::current(), "Must be"); \ ThreadInVMfromJava __tiv(current); \ <== !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! JavaThread* THREAD = current; /* For exception macros. */ \ debug_only(VMEntryWrapper __vew;) The stacktrace of the target (MainThread) at the point when NotifyFramePop is called is: DBG: post_method_exit_inner #4: t: MainThread meth: int NotifyFramePopStressTest.bar() DBG: ##### NATIVE stacktrace of JavaThread: 0x7f45a83abaf0 ##### Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code) V [libjvm.so+0xdb4f20] ThreadSelfSuspensionHandshake::do_thread(Thread*)+0x40 (javaThread.inline.hpp:153) V [libjvm.so+0xdb1c47] HandshakeOperation::do_handshake(JavaThread*)+0x47 (handshake.cpp:326) V [libjvm.so+0xdb1fde] HandshakeState::process_by_self(bool, bool)+0x2ae (handshake.cpp:584) V [libjvm.so+0x161bf85] SafepointMechanism::process(JavaThread*, bool, bool)+0x65 (safepointMechanism.cpp:159) V [libjvm.so+0x11a7761] ThreadStateTransition::transition_from_vm(JavaThread*, JavaThreadState, bool)+0xf1 (safepointMechanism.inline.hpp:83) V [libjvm.so+0x11a184c] JvmtiExport::post_method_exit(JavaThread*, Method*, frame)+0x13c (interfaceSupport.inline.hpp:140) V [libjvm.so+0xe5e777] InterpreterRuntime::post_method_exit(JavaThread*)+0x77 (interpreterRuntime.cpp:1258) j NotifyFramePopStressTest.bar()I+3 j NotifyFramePopStressTest.main([Ljava/lang/String;)V+64 j java.lang.invoke.LambdaForm$DMH+0x00007f45064063e0.invokeStatic(Ljava/lang/Object;Ljava/lang/Object;)V+10 java.base@24-internal j java.lang.invoke.LambdaForm$MH+0x00007f4506408c10.invoke(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;+33 java.base@24-internal j java.lang.invoke.Invokers$Holder.invokeExact_MT(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;+20 java.base@24-internal j jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+55 java.base@24-internal j jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+23 java.base@24-internal j java.lang.reflect.Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;+102 java.base@24-internal j com.sun.javatest.regtest.agent.MainWrapper$MainTask.run()V+134 j java.lang.Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V+5 java.base@24-internal j java.lang.Thread.run()V+19 java.base@24-internal v ~StubRoutines::call_stub 0x00007f459682fd01 V [libjvm.so+0xe7d83c] JavaCalls::call_helper(JavaValue*, methodHandle const&, JavaCallArguments*, JavaThread*)+0x48c (javaCalls.cpp:421) V [libjvm.so+0xe7df0c] JavaCalls::call_virtual(JavaValue*, Klass*, Symbol*, Symbol*, JavaCallArguments*, JavaThread*)+0x34c (javaCalls.cpp:329) V [libjvm.so+0xe7e126] JavaCalls::call_virtual(JavaValue*, Handle, Klass*, Symbol*, Symbol*, JavaThread*)+0x76 (javaCalls.cpp:191) V [libjvm.so+0xfec213] thread_entry(JavaThread*, JavaThread*)+0x93 (jvm.cpp:2910) V [libjvm.so+0xeb435c] JavaThread::thread_main_inner()+0xcc (javaThread.cpp:758) V [libjvm.so+0x17e2456] Thread::call_run()+0xb6 (thread.cpp:225) V [libjvm.so+0x14cb617] thread_native_entry(Thread*)+0x127 (os_linux.cpp:858) ################### The suggested fix is to use JRT_BLOCK in more precise place exactly where it is needed: diff --git a/src/hotspot/share/interpreter/interpreterRuntime.cpp b/src/hotspot/share/interpreter/interpreterRuntime.cpp index 525258b1ebd..14888f124b4 100644 --- a/src/hotspot/share/interpreter/interpreterRuntime.cpp +++ b/src/hotspot/share/interpreter/interpreterRuntime.cpp @@ -447,12 +447,7 @@ JRT_END // from a call, the expression stack contains the values for the bci at the // invoke w/o arguments (i.e., as if one were inside the call). // Note that the implementation of this method assumes it's only called when an exception has actually occured -JRT_ENTRY(address, InterpreterRuntime::exception_handler_for_exception(JavaThread* current, oopDesc* exception)) - // We get here after we have unwound from a callee throwing an exception - // into the interpreter. Any deferred stack processing is notified of - // the event via the StackWatermarkSet. - StackWatermarkSet::after_unwind(current); - +JRT_BLOCK_ENTRY(address, InterpreterRuntime::exception_handler_for_exception(JavaThread* current, oopDesc* exception)) LastFrameAccessor last_frame(current); Handle h_exception(current, exception); methodHandle h_method (current, last_frame.method()); @@ -460,6 +455,14 @@ JRT_ENTRY(address, InterpreterRuntime::exception_handler_for_exception(JavaThrea bool should_repeat; int handler_bci; int current_bci = last_frame.bci(); + address continuation = nullptr; + address handler_pc = nullptr; + + JRT_BLOCK + // We get here after we have unwound from a callee throwing an exception + // into the interpreter. Any deferred stack processing is notified of + // the event via the StackWatermarkSet. + StackWatermarkSet::after_unwind(current); if (current->frames_to_pop_failed_realloc() > 0) { // Allocation of scalar replaced object used in this frame @@ -552,8 +555,6 @@ JRT_ENTRY(address, InterpreterRuntime::exception_handler_for_exception(JavaThrea JvmtiExport::post_exception_throw(current, h_method(), last_frame.bcp(), h_exception()); } - address continuation = nullptr; - address handler_pc = nullptr; if (handler_bci < 0 || !current->stack_overflow_state()->reguard_stack((address) &continuation)) { // Forward exception to callee (leaving bci/bcp untouched) because (a) no // handler in this method, or (b) after a stack overflow there is not yet @@ -574,6 +575,7 @@ JRT_ENTRY(address, InterpreterRuntime::exception_handler_for_exception(JavaThrea continuation = (address)(intptr_t) handler_bci; #endif } + JRT_BLOCK_END // notify debugger of an exception catch // (this is good for exceptions caught in native methods as well) diff --git a/src/hotspot/share/prims/jvmtiExport.cpp b/src/hotspot/share/prims/jvmtiExport.cpp index 95cc54d9313..7f962e06a63 100644 --- a/src/hotspot/share/prims/jvmtiExport.cpp +++ b/src/hotspot/share/prims/jvmtiExport.cpp @@ -1810,7 +1810,8 @@ void JvmtiExport::post_method_entry(JavaThread *thread, Method* method, frame cu // for any thread that actually wants method entry, interp_only_mode is set return; } - if (mh->jvmti_mount_transition() || thread->is_in_any_VTMS_transition()) { + // pure continuations have no VTMS transitions but they use methods annotated with JvmtiMountTransition + if ((mh->jvmti_mount_transition() && state->is_virtual()) || thread->is_in_any_VTMS_transition()) { return; // no events should be posted if thread is in any VTMS transition } EVT_TRIG_TRACE(JVMTI_EVENT_METHOD_ENTRY, ("[%s] Trg Method Entry triggered %s.%s", @@ -1874,13 +1875,7 @@ void JvmtiExport::post_method_exit(JavaThread* thread, Method* method, frame cur } } - // Deferred transition to VM, so we can stash away the return oop before GC - // Note that this transition is not needed when throwing an exception, because - // there is no oop to retain. - JavaThread* current = thread; // for JRT_BLOCK - JRT_BLOCK - post_method_exit_inner(thread, mh, state, exception_exit, current_frame, value); - JRT_BLOCK_END + post_method_exit_inner(thread, mh, state, exception_exit, current_frame, value); if (result.not_null() && !mh->is_native()) { // We have to restore the oop on the stack for interpreter frames @@ -1894,7 +1889,8 @@ void JvmtiExport::post_method_exit_inner(JavaThread* thread, bool exception_exit, frame current_frame, jvalue& value) { - if (mh->jvmti_mount_transition() || thread->is_in_any_VTMS_transition()) { + // pure continuations have no VTMS transitions but they use methods annotated with JvmtiMountTransition + if ((mh->jvmti_mount_transition() && state->is_virtual()) || thread->is_in_any_VTMS_transition()) { return; // no events should be posted if thread is in any VTMS transition } @@ -1903,7 +1899,10 @@ void JvmtiExport::post_method_exit_inner(JavaThread* thread, (mh() == nullptr) ? "null" : mh()->klass_name()->as_C_string(), (mh() == nullptr) ? "null" : mh()->name()->as_C_string() )); + JavaThread* current = thread; // for JRT_BLOCK + if (state->is_enabled(JVMTI_EVENT_METHOD_EXIT)) { + JRT_BLOCK JvmtiEnvThreadStateIterator it(state); for (JvmtiEnvThreadState* ets = it.first(); ets != nullptr; ets = it.next(ets)) { if (ets->is_enabled(JVMTI_EVENT_METHOD_EXIT)) { @@ -1922,6 +1921,7 @@ void JvmtiExport::post_method_exit_inner(JavaThread* thread, } } } + JRT_BLOCK_END } JvmtiEnvThreadStateIterator it(state); @@ -1930,6 +1930,8 @@ void JvmtiExport::post_method_exit_inner(JavaThread* thread, int cur_frame_number = state->cur_stack_depth(); if (ets->is_frame_pop(cur_frame_number)) { + JRT_BLOCK + // we have a NotifyFramePop entry for this frame. // now check that this env/thread wants this event if (ets->is_enabled(JVMTI_EVENT_FRAME_POP)) { @@ -1953,6 +1955,7 @@ void JvmtiExport::post_method_exit_inner(JavaThread* thread, MutexLocker mu(JvmtiThreadState_lock); ets->clear_frame_pop(cur_frame_number); } + JRT_BLOCK_END } } } @@ -1970,7 +1973,8 @@ void JvmtiExport::post_single_step(JavaThread *thread, Method* method, address l if (state == nullptr) { return; } - if (mh->jvmti_mount_transition() || thread->is_in_any_VTMS_transition()) { + // pure continuations have no VTMS transitions but they use methods annotated with JvmtiMountTransition + if ((mh->jvmti_mount_transition() && state->is_virtual()) || thread->is_in_any_VTMS_transition()) { return; // no events should be posted if thread is in any VTMS transition } @@ -2134,12 +2138,15 @@ void JvmtiExport::notice_unwind_due_to_exception(JavaThread *thread, Method* met assert(!state->is_exception_caught(), "exception must not be caught yet."); state->set_exception_caught(); - if (mh->jvmti_mount_transition() || thread->is_in_any_VTMS_transition()) { + // pure continuations have no VTMS transitions but they use methods annotated with JvmtiMountTransition + if ((mh->jvmti_mount_transition() && state->is_virtual()) || thread->is_in_any_VTMS_transition()) { return; // no events should be posted if thread is in any VTMS transition } JvmtiEnvThreadStateIterator it(state); for (JvmtiEnvThreadState* ets = it.first(); ets != nullptr; ets = it.next(ets)) { if (ets->is_enabled(JVMTI_EVENT_EXCEPTION_CATCH) && (exception_handle() != nullptr)) { + JavaThread* current = thread; // for JRT_BLOCK + JRT_BLOCK EVT_TRACE(JVMTI_EVENT_EXCEPTION_CATCH, ("[%s] Evt ExceptionCatch sent %s.%s @ " INTX_FORMAT, JvmtiTrace::safe_get_thread_name(thread), @@ -2156,6 +2163,7 @@ void JvmtiExport::notice_unwind_due_to_exception(JavaThread *thread, Method* met jem.jni_methodID(), jem.location(), jem.exception()); } + JRT_BLOCK_END } } With the fix above the NotifyFramePopStressTest test from Chris does not fail anymore.
03-10-2024

It is nice you were able to catch this and reproduce reliably. Thank you for filing the bug! As I'd pointed last week we should have the same issue with the PopFrame and ForceEarlyReturn. I have no idea at the moment how to fix this issue. Obviously, there is a race here between return from the method and NotifyFramePop. The thread suspending point makes this transition visible and provides inconsistent state view. I'm not sure if hiding the last frame in the thread stack trace would help here. One of possible approaches to fix this would be to revert in time the relative order of suspending point and the MethodExit+FramePop event point. Not sure, if it is feasible though.
24-09-2024

Chris, I hope you are going to share the test when it is ready. :)
24-09-2024

> I'm not sure if hiding the last frame in the thread stack trace would help here. That would help assuming that the last frame is hidden from all APIs that expose the stack.
23-09-2024