JDK21 serviceability/jvmti/vthread/ThreadListStackTracesTest/ThreadListStackTracesTest.java RuntimeException: JVMTI multi thread state is wrong #18089

JasonFengJ9 · 2023-09-07T14:50:27Z

Failure link

From an internal build(osxrt1):

03:27:31  openjdk version "21-internal" 2023-09-19
03:27:31  OpenJDK Runtime Environment (build 21-internal-adhoc.jenkins.BuildJDK21x86-64macPersonal)
03:27:31  Eclipse OpenJ9 VM (build master-7599bde8a13, JRE 21 Mac OS X amd64-64-Bit Compressed References 20230906_50 (JIT enabled, AOT enabled)
03:27:31  OpenJ9   - 7599bde8a13
03:27:31  OMR      - 873ac5d377a
03:27:31  JCL      - 154f45ddce4 based on jdk-21+35)

Rerun in Grinder - Change TARGET to run only the failed test targets.

Optional info

Failure output (captured from console output)

03:29:53  variation: Mode150
03:29:53  JVM_OPTIONS:  -XX:+UseCompressedOops 

03:32:59  TEST: serviceability/jvmti/vthread/ThreadListStackTracesTest/ThreadListStackTracesTest.java

03:32:59  STDERR:
03:32:59  java.lang.RuntimeException: JVMTI multi thread state is wrong
03:32:59  	at ThreadListStackTracesTest.failed(ThreadListStackTracesTest.java:87)
03:32:59  	at ThreadListStackTracesTest.checkStates(ThreadListStackTracesTest.java:132)
03:32:59  	at ThreadListStackTracesTest.checkReentrantLock(ThreadListStackTracesTest.java:101)
03:32:59  	at ThreadListStackTracesTest.main(ThreadListStackTracesTest.java:90)
03:32:59  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
03:32:59  	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
03:32:59  	at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
03:32:59  	at java.base/java.lang.Thread.run(Thread.java:1595)
03:32:59  
03:32:59  JavaTest Message: Test threw exception: java.lang.RuntimeException: JVMTI multi thread state is wrong

03:33:09  serviceability_jvmti_j9_0_FAILED

50x serviceability_jvmti_j9_0 internal grinder - this failure wasn't reproduced

FYI @babsingh

The text was updated successfully, but these errors were encountered:

babsingh · 2023-09-13T16:48:46Z

Locally, I was able to reproduce the failure 1 time in 250 runs. The default test output is insufficient to properly triage. The test will need to be updated to print/output more debug information. @thallium Shall I assign this issue to you?

thallium · 2023-09-13T16:55:06Z

@babsingh Sure I can take a look at this.

thallium · 2023-09-22T20:50:04Z

A few things that I have observed:

when the test failed, it got RUNNABLE state instead of WAITING
the thread state changed to WAITING after singleState and multiState is set, so the check vt.getState() != expState passed

babsingh · 2023-09-28T14:40:24Z

@thallium Documenting my Slack notes (from 25 Sep 23) here since they highlight the next steps for the issue. Can you provide me a progress update, what will be your next steps and a time estimate to resolve this issue?

Test source code

https://github.com/ibmruntimes/openj9-openjdk-jdk21/blob/c2fb960c3951006ffe09af0241e95028e3cc8c09/test/hotspot/jtreg/serviceability/jvmti/vthread/ThreadListStackTracesTest/ThreadListStackTracesTest.java#L128-L132

        // [ERROR] 03:32:59  java.lang.RuntimeException: JVMTI multi thread state is wrong

        if ((singleState & jvmtiExpState) == 0) {
            failed("JVMTI single thread state is wrong");
        }
        if ((multiState & jvmtiExpState) == 0) {
            failed("JVMTI multi thread state is wrong");
        }

The above two checks fail intermittently.

        int singleState = getStateSingle(vt);
        int multiState = getStateMultiple(vt, Thread.currentThread());

getStateSingle and getStateMultiple use JVMTI GetThreadListStackTraces to get the thread state.
Check the code for JVMTI GetThreadListStackTraces.
Find under what circumstances JVMTI GetThreadListStackTraces can return RUNNABLE instead of WAITING (expected).
Two perspectives to explore:
- the test might be wrong, and it doesn't check the correct behaviour which is specified in the JVMTI specification; OR
- our implementation is wrong, and we don't follow the JVMTI specification for GetThreadListStackTraces.

thallium · 2023-09-29T01:54:39Z

Current update: JVMTI GetThreadListStackTraces calls getVirtualThreadState which uses VirtualThread.state to make the JVMTI thread state. I tried to get a dump right after the test failed but VirtualThread.state appeared to be normal in the dump. I'll try to run the test more times to catch the bad state, but I'm not sure what I can look at if I got a useful dump.

babsingh · 2023-09-29T15:57:24Z

getVirtualThreadState which uses VirtualThread.state to make the JVMTI thread state

VirtualThread.state is not always used.

For mounted virtual threads (NULL != targetThread), getThreadStateHelper is used.

openj9/runtime/jvmti/jvmtiHelpers.c

Lines 821 to 826 in da4cabf

    
           if (NULL != targetThread) { 
        
           	vm->internalVMFunctions->haltThreadForInspection(currentThread, targetThread); 
        
           	rc = getThreadStateHelper(currentThread, targetThread->carrierThreadObject, targetThread); 
        
           	vm->internalVMFunctions->resumeThreadForInspection(currentThread, targetThread); 
        
           } else { 
        
           	jint vThreadState = (jint) J9VMJAVALANGVIRTUALTHREAD_STATE(currentThread, vThreadObject);

Even for unmounted threads, java.lang.Thread.container field is used in some cases.

openj9/runtime/jvmti/jvmtiHelpers.c

Lines 841 to 852 in da4cabf

    
           jlThread = (*env)->FindClass(env, "java/lang/Thread"); 
        
           if (NULL != jlThread) { 
        
           	fid = (*env)->GetFieldID(env, jlThread, "container", "Ljdk/internal/vm/ThreadContainer;"); 
        
           } 
        
           if ((NULL != fid) 
        
           	&& (NULL == (*env)->GetObjectField(env, thread, fid)) 
        
           ) { 
        
           	rc = JVMTI_JAVA_LANG_THREAD_STATE_NEW; 
        
           } else { 
        
           	rc = JVMTI_JAVA_LANG_THREAD_STATE_RUNNABLE; 
        
           } 
        
           vm->internalVMFunctions->internalEnterVMFromJNI(currentThread);

but I'm not sure what I can look at if I got a useful dump.

Add debug code (print statements) in getVirtualThreadState (at multiple points) to see how the thread state is being evaluated. Once we know the code path taken to evaluate the incorrect state, then we can figure out what is causing this failure.

babsingh · 2023-10-23T18:11:34Z

Moving to the 0.44 release since the failure is highly intermittent.

babsingh · 2023-10-26T02:07:57Z

During failure, the test output is ...

STDOUT:
grabbing reentrantLock
State: expected: RUNNABLE single: 191 multi: 5
STDERR:
java.lang.RuntimeException: JVMTI multi thread state is wrong

When the test passes, the test output is ...

STDOUT:
grabbing reentrantLock
State: expected: WAITING single: 291 multi: 291
entering synchronized statement
State: expected: BLOCKED single: 401 multi: 401
entered synchronized statement
STDERR:
STATUS:Passed.

The problem is in the TEST. Test code, ThreadListStackTracesTest.checkStates:

    private static void checkStates(Thread vt, Thread.State expState) {
        int singleState = getStateSingle(vt);
        int multiState = getStateMultiple(vt, Thread.currentThread());
        int jvmtiExpState = (expState == Thread.State.WAITING) ?
                            JVMTI_THREAD_STATE_WAITING :
                            JVMTI_THREAD_STATE_BLOCKED_ON_MONITOR_ENTER;

        System.out.printf("State: expected: %s single: %x multi: %x\n",
                          vt.getState(), singleState, multiState);

        if (vt.getState() != expState) {
            failed("Java thread state is wrong");
        }
        if ((singleState & jvmtiExpState) == 0) {
            failed("JVMTI single thread state is wrong");
        }
        if ((multiState & jvmtiExpState) == 0) {
            failed("JVMTI multi thread state is wrong");
        }
    }

getStateSingle and getStateMultiple use JVMTI GetThreadListStackTraces to get the thread state.

Test code, ReentrantLockTestTask.run represents the virtual thread:

class ReentrantLockTestTask extends TestTask {
    public void run() {
        log("grabbing reentrantLock");
        threadReady = true;
        ThreadListStackTracesTest.reentrantLock.lock();
        log("grabbed reentrantLock");
    }
}

checkStates is invoked when the virtual thread runs reentrantLock.lock().

Test code, ThreadListStackTracesTest.checkReentrantLock:

    private static void checkReentrantLock() throws InterruptedException {
        final Thread.State expState = Thread.State.WAITING;
        reentrantLock.lock();
        String name = "ReentrantLockTestTask";
        TestTask task = new ReentrantLockTestTask();
        Thread vt = Thread.ofVirtual().name(name).start(task);
        task.ensureReady(vt, expState);
        // checkStates is concurrently run with ReentrantLockTestTask.run
        checkStates(vt, expState);
    }

task.ensureReady pauses execution until threadReady is true and vt.getState() reaches the expected state. The expected thread state in checkReentrantLock is Thread.State.WAITING. The test assumes that the expected thread state is only achieved when reentrantLock.lock() is invoked. This is not true. Thread.State.WAITING can also be achieved when the virtual thread scheduler unmounts and parks the virtual thread. There is ambiguity in the test code. To resolve this issue, we need to make sure that checkStates is invoked once the virtual thread is waiting to acquire the lock, reentrantLock.lock().

The below changes to the test code should resolve the reported failure:

    public void ensureReady(Thread vt, Thread.State expState) {
    	// sleep for 1 second to allow the thread to reach the expected state
    	sleep(1000);
        // wait while the thread is not ready or thread state is unexpected
        while (!threadReady || (vt.getState() != expState)) {
            sleep(1);
        }
    }
    
    ...

    private static void checkReentrantLock() throws InterruptedException {
        final Thread.State expState = Thread.State.WAITING;
        reentrantLock.lock();
        String name = "ReentrantLockTestTask";
        TestTask task = new ReentrantLockTestTask();
        Thread vt = Thread.ofVirtual().name(name).start(task);
        task.ensureReady(vt, expState);
        // wait until vt is waiting to acquire the lock
        while (!reentrantLock.hasQueuedThread(vt)) {
        	sleep(1);
        }
        checkStates(vt, expState);
    }

Refer to the Javadoc for ReentrantLock to understand the ReentrantLock.hasQueuedThread method.

@singh264 Can you verify the above analysis? If you agree, can you create PRs that modify the test in the JDK21 and JDK-next repos?

JasonFengJ9 · 2023-10-27T21:09:46Z

JDK21 x86-64_mac(mac11x64rt04)

java version "21.0.1-beta" 2023-10-17
IBM Semeru Runtime Certified Edition 21.0.1+12-202310261403 (build 21.0.1-beta+12-202310261403)
Eclipse OpenJ9 VM 21.0.1+12-202310261403 (build master-66e3fd1da, JRE 21 Mac OS X amd64-64-Bit Compressed References 20231026_22 (JIT enabled, AOT enabled)
OpenJ9   - 66e3fd1da
OMR      - 071c0c25b
JCL      - c06eaf638 based on jdk-21.0.1+12)

[2023-10-26T15:00:50.188Z] variation: Mode650
[2023-10-26T15:00:50.188Z] JVM_OPTIONS:  -XX:-UseCompressedOops 

[2023-10-26T15:03:11.619Z] TEST: serviceability/jvmti/vthread/ThreadListStackTracesTest/ThreadListStackTracesTest.java

[2023-10-26T15:03:11.620Z] STDERR:
[2023-10-26T15:03:11.620Z] java.lang.RuntimeException: JVMTI multi thread state is wrong
[2023-10-26T15:03:11.620Z] 	at ThreadListStackTracesTest.failed(ThreadListStackTracesTest.java:87)
[2023-10-26T15:03:11.620Z] 	at ThreadListStackTracesTest.checkStates(ThreadListStackTracesTest.java:132)
[2023-10-26T15:03:11.620Z] 	at ThreadListStackTracesTest.checkReentrantLock(ThreadListStackTracesTest.java:101)
[2023-10-26T15:03:11.620Z] 	at ThreadListStackTracesTest.main(ThreadListStackTracesTest.java:90)
[2023-10-26T15:03:11.620Z] 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
[2023-10-26T15:03:11.620Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
[2023-10-26T15:03:11.620Z] 	at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
[2023-10-26T15:03:11.620Z] 	at java.base/java.lang.Thread.run(Thread.java:1595)

[2023-10-26T15:03:30.804Z] serviceability_jvmti_j9_1_FAILED

singh264 · 2023-10-30T15:39:40Z

@babsingh I will verify the analysis.

singh264 · 2023-11-13T21:35:21Z

@babsingh I will verify the analysis.

It seems like the virtual thread scheduler does not unmount and park the virtual thread when the state of the thread changes from Thread.State.RUNNABLE to Thread.State.WAITING in ensureReady(..) as virtualThreadUnmountBegin(..) and virtualThreadUnmountEnd(..) are only called when the reentrantLock parks the virtual thread, which occurs after the main thread indicates the test failure by completing ensureReady(..) and checkStates(..).

Before ReentrantLockTestTask starts, I observe that VirtualThread.compareAndSetState(..) is called to update the state from VirtualThread.NEW <-> Thread.State.NEW to VirtualThread.STARTED <-> Thread.State.RUNNABLE, and from VirtualThread.STARTED <-> Thread.State.RUNNABLE to VirtualThread.RUNNING <-> (Thread.State.RUNNABLE or carrierThread.threadState()).

Since the reentrantLock parks the virtual thread after the main thread indicates the test failure, it seems like carrierThread.threadState() transitions from Thread.State.WAITING to Thread.State.RUNNING (before getStateMultiple(..)) and back to Thread.State.WAITING (before if (vt.getState() != expState)).

After the reentrantLock parks the virtual thread, I observe that VirtualThread.setState(..) is called to update the state from VirtualThread.RUNNING <-> (Thread.State.RUNNABLE or carrierThread.threadState()) to VirtualThread.PARKING <-> Thread.State.RUNNABLE in VirtualThread.park(), and from VirtualThread.PARKING <-> Thread.State.RUNNABLE to VirtualThread.PARKED <-> Thread.State.WAITING in VirtualThread.afterYield().

Adjust ThreadListStackTracesTest for checkReentrantLock to be ready when the virtual thread state is Thread.State.WAITING after the reentrant lock parks the virutal thread. When the virtual thread is mounted, the virtual thread state, which is obtained from the carrier thread, can transition between Thread.State.WAITING and Thread.State.RUNNABLE before the reentrant lock parks the virtual thread. Issue: eclipse-openj9/openj9#18089 Signed-off-by: Amarpreet Singh <[email protected]>

Adjust ThreadListStackTracesTest for checkReentrantLock to be ready when the virtual thread state is Thread.State.WAITING after the reentrant lock parks the virtual thread. When the virtual thread is mounted, the virtual thread state, which is obtained from the carrier thread, can transition between Thread.State.WAITING and Thread.State.RUNNABLE before the reentrant lock parks the virtual thread. Issue: eclipse-openj9/openj9#18089 Signed-off-by: Amarpreet Singh <[email protected]>

singh264 · 2023-11-16T17:10:01Z

If you agree, can you create PRs that modify the test in the JDK21 and JDK-next repos?

@babsingh the PRs that modify the test in the JDK21 and JDK-next repos are at ibmruntimes/openj9-openjdk-jdk21#63 and ibmruntimes/openj9-openjdk-jdk#693.

I adjusted the test, which passed 2500 times locally, by including while (!reentrantLock.hasQueuedThread(vt)) { before task.ensureReady(vt, expState); since the reentrant lock modifies the state of the virtual thread to Thread.State.WAITING by parking the virtual thread after it is added to the wait queue of the reentrant lock.

Adjust ThreadListStackTracesTest for checkReentrantLock to be ready when the virtual thread state is WAITING after the reentrant lock parks the virtual thread. When the virtual thread is mounted, the virtual thread state, which is obtained from the carrier thread, can transition between WAITING and RUNNABLE before the reentrant lock parks the virtual thread. Issue: eclipse-openj9/openj9#18089 Signed-off-by: Amarpreet Singh <[email protected]>

Adjust ThreadListStackTracesTest for checkReentrantLock to be ready when the virtual thread state is WAITING after the reentrant lock parks the virtual thread. When the virtual thread is mounted, the virtual thread state, which is obtained from the carrier thread, can transition between WAITING and RUNNABLE before the virtual thread is parked on the lock. Issue: eclipse-openj9/openj9#18089 Signed-off-by: Amarpreet Singh <[email protected]>

babsingh · 2023-11-20T18:02:05Z

Fixed via

JasonFengJ9 added comp:vm test failure comp:jvmti jdk21 labels Sep 7, 2023

JasonFengJ9 added this to the Java 21 (0.42) milestone Sep 7, 2023

babsingh assigned babsingh and unassigned babsingh Sep 7, 2023

babsingh assigned thallium Sep 13, 2023

fengxue-IS added the project:loom Used to track Project Loom related work label Sep 16, 2023

babsingh modified the milestones: Java 21 (0.42), Release 0.44 (Java 8, 11, 17, 21) Apr refresh Oct 23, 2023

babsingh unassigned thallium Oct 26, 2023

babsingh assigned singh264 Oct 30, 2023

This was referenced Nov 16, 2023

Adjust ThreadListStackTracesTest for checkReentrantLock ibmruntimes/openj9-openjdk-jdk21#63

Merged

Adjust ThreadListStackTracesTest for checkReentrantLock ibmruntimes/openj9-openjdk-jdk#693

Merged

singh264 mentioned this issue Nov 20, 2023

(0.42) Adjust ThreadListStackTracesTest for checkReentrantLock ibmruntimes/openj9-openjdk-jdk21#70

Merged

singh264 mentioned this issue Nov 20, 2023

(0.43) Adjust ThreadListStackTracesTest for checkReentrantLock ibmruntimes/openj9-openjdk-jdk21#71

Merged

babsingh closed this as completed Nov 20, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

JDK21 serviceability/jvmti/vthread/ThreadListStackTracesTest/ThreadListStackTracesTest.java RuntimeException: JVMTI multi thread state is wrong #18089

JDK21 serviceability/jvmti/vthread/ThreadListStackTracesTest/ThreadListStackTracesTest.java RuntimeException: JVMTI multi thread state is wrong #18089

JasonFengJ9 commented Sep 7, 2023 •

edited

Loading

babsingh commented Sep 13, 2023

thallium commented Sep 13, 2023

thallium commented Sep 22, 2023

babsingh commented Sep 28, 2023 •

edited

Loading

thallium commented Sep 29, 2023

babsingh commented Sep 29, 2023

babsingh commented Oct 23, 2023

babsingh commented Oct 26, 2023 •

edited

Loading

JasonFengJ9 commented Oct 27, 2023

singh264 commented Oct 30, 2023

singh264 commented Nov 13, 2023 •

edited

Loading

singh264 commented Nov 16, 2023

babsingh commented Nov 20, 2023

JDK21 serviceability/jvmti/vthread/ThreadListStackTracesTest/ThreadListStackTracesTest.java RuntimeException: JVMTI multi thread state is wrong #18089

JDK21 serviceability/jvmti/vthread/ThreadListStackTracesTest/ThreadListStackTracesTest.java RuntimeException: JVMTI multi thread state is wrong #18089

Comments

JasonFengJ9 commented Sep 7, 2023 • edited Loading

Failure link

Optional info

Failure output (captured from console output)

babsingh commented Sep 13, 2023

thallium commented Sep 13, 2023

thallium commented Sep 22, 2023

babsingh commented Sep 28, 2023 • edited Loading

Test source code

thallium commented Sep 29, 2023

babsingh commented Sep 29, 2023

babsingh commented Oct 23, 2023

babsingh commented Oct 26, 2023 • edited Loading

JasonFengJ9 commented Oct 27, 2023

singh264 commented Oct 30, 2023

singh264 commented Nov 13, 2023 • edited Loading

singh264 commented Nov 16, 2023

babsingh commented Nov 20, 2023

JasonFengJ9 commented Sep 7, 2023 •

edited

Loading

babsingh commented Sep 28, 2023 •

edited

Loading

babsingh commented Oct 26, 2023 •

edited

Loading

singh264 commented Nov 13, 2023 •

edited

Loading