JDK-8341273 : JVMTI is not properly hiding some continuation related methods
  • Type: Bug
  • Component: hotspot
  • Sub-Component: jvmti
  • Affected Version: 24
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2024-09-30
  • Updated: 2024-11-06
  • Resolved: 2024-10-29
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 b22Fixed
Related Reports
Relates :  
Description
Continuation.yield0() is showing up in the stack traces. It is not suppose to since it is a method that is suppose to be hidden. The method is being included in GetStackTrace, and also GetFrameCount.

The following simple test case and jdb session demonstrate the issue. Note the reason for setting the breakpoint is so jdb learns about the Virtual thread. Otherwise it won't show up in the threads list.

Main {
    public static void main(String[] args) throws Exception {
        Thread thread = Thread.ofVirtual().unstarted(Main::test);
        System.out.println(thread);
        thread.start();
        thread.join();
    }
    
    static void test() {
        try {
            Thread.sleep(1000000);
        } catch (InterruptedException e) {
        }
    }
}

$ jdb Main
Initializing jdb ...
> stop at Main:11
Deferring breakpoint Main:11.
It will be set after the class is loaded.
> run
run Main
Set uncaught java.lang.Throwable
Set deferred uncaught java.lang.Throwable
> 
VM Started: Set deferred breakpoint Main:13
VirtualThread[#34]/new

Breakpoint hit: "thread=", Main.test(), line=13 bci=0
13                Thread.sleep(1000000);

[1] cont
> suspend
All threads suspended.
> threads
Group system:
  (java.lang.ref.Reference$ReferenceHandler)406 Reference Handler       running
  (java.lang.ref.Finalizer$FinalizerThread)407  Finalizer               cond. waiting
  (java.lang.Thread)408                         Signal Dispatcher       running
  (java.lang.Thread)405                         Notification Thread     running
Group main:
  (java.lang.Thread)1                           main                    cond. waiting
Group InnocuousThreadGroup:
  (jdk.internal.misc.InnocuousThread)432        Common-Cleaner          cond. waiting
  (jdk.internal.misc.InnocuousThread)762        VirtualThread-unparker  cond. waiting
Group CarrierThreads:
  (jdk.internal.misc.CarrierThread)755          ForkJoinPool-1-worker-1 cond. waiting
Group VirtualThreads:
  (java.lang.VirtualThread)759                                          cond. waiting
> where 759
  [1] jdk.internal.vm.Continuation.yield0 (Continuation.java:360)
  [2] jdk.internal.vm.Continuation.yield (Continuation.java:351)
  [3] java.lang.VirtualThread.yieldContinuation (VirtualThread.java:526)
  [4] java.lang.VirtualThread.parkNanos (VirtualThread.java:716)
  [5] java.lang.VirtualThread.sleepNanos (VirtualThread.java:888)
  [6] java.lang.Thread.sleepNanos (Thread.java:495)
  [7] java.lang.Thread.sleep (Thread.java:528)
  [8] Main.test (Main.java:13)
  [9] Main$$Lambda/0x00007f0fdb000a18.run (null)
  [10] java.lang.Thread.runWith (Thread.java:1,589)
  [11] java.lang.VirtualThread.run (VirtualThread.java:404)
  [12] java.lang.VirtualThread$VThreadContinuation$1.run (VirtualThread.java:217)
  [13] jdk.internal.vm.Continuation.enter0 (Continuation.java:320)
  [14] jdk.internal.vm.Continuation.enter (Continuation.java:312)

Comments
Changeset: 60364ef0 Branch: master Author: Serguei Spitsyn <sspitsyn@openjdk.org> Date: 2024-10-29 19:59:43 +0000 URL: https://git.openjdk.org/jdk/commit/60364ef0010bde2933c22bf581ff8b3700c4afd6
29-10-2024

There is one more NotifyFramePop issue explained by Chris: >>> I think this might have something to do with the vthread terminating. We get to the point where the stack looks like this (using GetStackTrace): 0: jdk/internal/event/VirtualThreadEndEvent: isTurnedOn()Z 1: java/lang/VirtualThread: run(Ljava/lang/Runnable;)V 2: java/lang/VirtualThread$VThreadContinuation$1: run()V 3: jdk/internal/vm/Continuation: enter0()V 4: jdk/internal/vm/Continuation: enter(Ljdk/internal/vm/Continuation;Z)V At this point a NotifyFramePop has been done on frame 0 and 1. I get a FRAME_POP event, and now the stack looks like: 0: java/lang/VirtualThread: run(Ljava/lang/Runnable;)V 1: java/lang/VirtualThread$VThreadContinuation$1: run()V 2: jdk/internal/vm/Continuation: enter0()V 3: jdk/internal/vm/Continuation: enter(Ljdk/internal/vm/Continuation;Z)V So at this point there is still a NotifyFramePop on VirtualThread.run(). A bit later, without seeing another FRAME_POP event, the stack looks like: 0: java/lang/VirtualThread$VThreadContinuation$1: run()V 1: jdk/internal/vm/Continuation: enter0()V 2: jdk/internal/vm/Continuation: enter(Ljdk/internal/vm/Continuation;Z)V At this point the debug agent gets a VTHREAD_END event and starts calling ClearFramePop on all outstanding notifies. It gets a JVMTI_ERROR_ILLEGAL_ARGUMENT because the depth of the outstanding pop is 4, but the current depth is 3, so -1 gets passed as the depth to ClearFramePop. The error isn’t surprising given that this frame has already been popped, and we never got the FRAME_POP event for it, so it wasn’t removed from the book keeping. The question is how did the frame get popped without generating the FRAME_POP event. <<<<
10-10-2024

A pull request was submitted for review. Branch: master URL: https://git.openjdk.org/jdk/pull/21397 Date: 2024-10-07 22:03:36 +0000
07-10-2024

This bug is also causing issues with NotifyFramePop. If NotifyFramePop is done on the yield0() frame, when yield0() returns there is no FRAME_POP event. This is because JVMTI disables events while executing in yield0(). JVMTI does not clear out the NotifyFramePop in this case, and the next time we return from the same depth, the FRAME_EVENT is delivered, but of course it is for the wrong method return. As an example, I have a test case where the debug agent does a NotifyFramePop with the following stack trace: [21:10:44.76] debugee.stdout> JVMTI Stack Trace for thread thread1: frame count: 15 [21:10:44.76] debugee.stdout> 0: jdk/internal/vm/Continuation: yield0(Ljdk/internal/vm/ContinuationScope;Ljdk/internal/vm/Continuation;)Z [21:10:44.77] debugee.stdout> 1: jdk/internal/vm/Continuation: yield(Ljdk/internal/vm/ContinuationScope;)Z [21:10:44.77] debugee.stdout> 2: java/lang/VirtualThread: yieldContinuation()Z [21:10:44.77] debugee.stdout> 3: java/lang/VirtualThread: parkNanos(J)V [21:10:44.77] debugee.stdout> 4: java/lang/System$2: parkVirtualThread(J)V [21:10:44.77] debugee.stdout> 5: java/util/concurrent/locks/LockSupport: parkNanos(Ljava/lang/Object;J)V [21:10:44.77] debugee.stdout> 6: java/util/concurrent/locks/AbstractQueuedSynchronizer$ConditionObject: await(JLjava/util/concurrent/TimeUnit;)Z [21:10:44.78] debugee.stdout> 7: nsk/share/jdi/ThreadState: waitForState(Ljava/lang/String;)V [21:10:44.78] debugee.stdout> 8: nsk/share/jdi/ThreadState: setAndWait(Ljava/lang/String;Ljava/lang/String;)V [21:10:44.78] debugee.stdout> 9: nsk/jdi/StepRequest/addClassFilter_rt/Thread1filter_rt003a: run()V [21:10:44.78] debugee.stdout> 10: java/lang/Thread: runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V [21:10:44.78] debugee.stdout> 11: java/lang/VirtualThread: run(Ljava/lang/Runnable;)V [21:10:44.79] debugee.stdout> 12: java/lang/VirtualThread$VThreadContinuation$1: run()V [21:10:44.79] debugee.stdout> 13: jdk/internal/vm/Continuation: enter0()V [21:10:44.79] debugee.stdout> 14: jdk/internal/vm/Continuation: enter(Ljdk/internal/vm/Continuation;Z)V But the FRAME_EVENT is delivered with the following stack trace. Note the method we are returning from is at the same depth as yield0() when NotifyFramePop was called. [19:39:16.249] debugee.stdout> JVMTI Stack Trace for thread thread1: frame count: 15 [19:39:16.249] debugee.stdout> 0: java/lang/Object: <init>()V [19:39:16.249] debugee.stdout> 1: java/lang/AbstractStringBuilder: <init>(I)V [19:39:16.249] debugee.stdout> 2: java/lang/StringBuilder: <init>()V [19:39:16.249] debugee.stdout> 3: java/util/Formatter: <init>()V [19:39:16.249] debugee.stdout> 4: java/lang/String: format(Ljava/lang/String;[Ljava/lang/Object;)Ljava/lang/String; [19:39:16.250] debugee.stdout> 5: nsk/share/jdi/ThreadState: format(Ljava/lang/String;Ljava/lang/String;)Ljava/lang/String; [19:39:16.250] debugee.stdout> 6: nsk/share/jdi/ThreadState: log(Ljava/lang/String;Ljava/lang/String;)V [19:39:16.250] debugee.stdout> 7: nsk/share/jdi/ThreadState: waitForState(Ljava/lang/String;)V [19:39:16.250] debugee.stdout> 8: nsk/share/jdi/ThreadState: setAndWait(Ljava/lang/String;Ljava/lang/String;)V [19:39:16.250] debugee.stdout> 9: nsk/jdi/StepRequest/addClassFilter_rt/Thread1filter_rt003a: run()V [19:39:16.250] debugee.stdout> 10: java/lang/Thread: runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V [19:39:16.250] debugee.stdout> 11: java/lang/VirtualThread: run(Ljava/lang/Runnable;)V [19:39:16.250] debugee.stdout> 12: java/lang/VirtualThread$VThreadContinuation$1: run()V [19:39:16.250] debugee.stdout> 13: jdk/internal/vm/Continuation: enter0()V [19:39:16.250] debugee.stdout> 14: jdk/internal/vm/Continuation: enter(Ljdk/internal/vm/Continuation;Z)V
30-09-2024