Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Timeout in GetThreadStateTest #18502

Closed
babsingh opened this issue Nov 21, 2023 · 1 comment
Closed

Timeout in GetThreadStateTest #18502

babsingh opened this issue Nov 21, 2023 · 1 comment
Labels
comp:jvmti comp:vm test failure
Milestone
Java 21 (0.42)

Comments

@babsingh
Copy link
Contributor

Failing build

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_extended.openjdk_s390x_linux_Personal/6/consoleFull

This failure is first seen in #18459.

Test source code

GetThreadStateTest.java#L283: timeout occurs while executing testParkWhenPinned.

Potential issue

A deadlock occurs while acquiring VThreadInspector because the virtual thread parks without exiting VThreadTransitionCritical.

openj9/runtime/jvmti/jvmtiHelpers.cpp

Lines 822 to 831 in ac47064

getVirtualThreadState(J9VMThread *currentThread, jthread thread)
{
J9JavaVM* vm = currentThread->javaVM;
jint rc = 0;
J9VMThread *targetThread = NULL;
Assert_JVMTI_notNull(thread);
Assert_JVMTI_mustHaveVMAccess(currentThread);
rc = getVMThread(
currentThread, thread, &targetThread, JVMTI_ERROR_NONE,
J9JVMTI_GETVMTHREAD_ERROR_ON_NULL_JTHREAD);

Java stack trace

04:52:36  Running jstack on process 2036823
04:52:36  2023-11-16T09:52:27.705779680
04:52:36  Virtual machine: 2036823 JVM information:
04:52:36  JRE 21 Linux s390x-64-Bit Compressed References 20231115_125 (JIT enabled, AOT enabled)
04:52:36  OpenJ9   - f79fde9d1ca
04:52:36  OMR      - 07a175a4d23
04:52:36  JCL      - 4b666c7419b based on jdk-21.0.1+12
04:52:36  
04:52:36  "main" prio=5 Id=2 WAITING
04:52:36  	at [email protected]/java.lang.Object.waitImpl(Native Method)
04:52:36  	at [email protected]/java.lang.Object.wait(Object.java:255)
04:52:36  	at [email protected]/java.lang.Object.wait(Object.java:221)
04:52:36  	at [email protected]/java.lang.Thread.join(Thread.java:2105)
04:52:36  	at [email protected]/java.lang.Thread.join(Thread.java:2181)
04:52:36  	at app//com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:85)
04:52:36  
04:52:36  "JIT Compilation Thread-000" prio=10 Id=4 RUNNABLE
04:52:36  
04:52:36  "JIT Compilation Thread-001 Suspended" prio=10 Id=5 RUNNABLE
04:52:36  
04:52:36  "JIT Compilation Thread-002 Suspended" prio=10 Id=6 RUNNABLE
04:52:36  
04:52:36  "JIT Compilation Thread-003 Suspended" prio=10 Id=7 RUNNABLE
04:52:36  
04:52:36  "JIT Compilation Thread-004 Suspended" prio=10 Id=8 RUNNABLE
04:52:36  
04:52:36  "JIT Compilation Thread-005 Suspended" prio=10 Id=9 RUNNABLE
04:52:36  
04:52:36  "JIT Compilation Thread-006 Suspended" prio=10 Id=10 RUNNABLE
04:52:36  
04:52:36  "JIT Diagnostic Compilation Thread-007 Suspended" prio=10 Id=11 RUNNABLE
04:52:36  
04:52:36  "JIT-SamplerThread" prio=10 Id=12 TIMED_WAITING
04:52:36  
04:52:36  "IProfiler" prio=5 Id=13 RUNNABLE
04:52:36  
04:52:36  "Common-Cleaner" prio=8 Id=3 TIMED_WAITING
04:52:36  	at [email protected]/java.lang.Object.waitImpl(Native Method)
04:52:36  	at [email protected]/java.lang.Object.wait(Object.java:255)
04:52:36  	at [email protected]/java.lang.Object.wait(Object.java:221)
04:52:36  	at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
04:52:36  	at [email protected]/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
04:52:36  	at [email protected]/java.lang.Thread.run(Thread.java:1595)
04:52:36  	at [email protected]/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)
04:52:36  
04:52:36  "Concurrent Mark Helper" prio=1 Id=14 RUNNABLE
04:52:36  
04:52:36  "GC Worker" prio=5 Id=15 RUNNABLE
04:52:36  
04:52:36  "GC Worker" prio=5 Id=16 RUNNABLE
04:52:36  
04:52:36  "GC Worker" prio=5 Id=17 RUNNABLE
04:52:36  
04:52:36  "Attach API wait loop" prio=10 Id=20 RUNNABLE
04:52:36  	at [email protected]/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
04:52:36  	at [email protected]/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
04:52:36  	at [email protected]/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
04:52:36  	at [email protected]/openj9.internal.tools.attach.target.WaitLoop.run(WaitLoop.java:157)
04:52:36  
04:52:36  "MainThread" prio=5 Id=21 TIMED_WAITING
04:52:36  	at [email protected]/java.lang.Thread.sleepImpl(Native Method)
04:52:36  	at [email protected]/java.lang.Thread.sleep(Thread.java:516)
04:52:36  	at app//GetThreadStateTest.await(GetThreadStateTest.java:364)
04:52:36  	at app//GetThreadStateTest.testParkWhenPinned(GetThreadStateTest.java:304)
04:52:36  	at [email protected]/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
04:52:36  	at [email protected]/java.lang.reflect.Method.invoke(Method.java:580)
04:52:36  	at app//org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)
04:52:36  	at app//org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
04:52:36  	at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
04:52:36  	at app//org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
04:52:36  	at app//org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
04:52:36  	at app//org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
04:52:36  	at app//org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
04:52:36  	at app//org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
04:52:36  	at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
04:52:36  	at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
04:52:36  	at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
04:52:36  	at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
04:52:36  	at app//org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
04:52:36  	at app//org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
04:52:36  	at app//org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:217)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
04:52:36  	at app//org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:213)
04:52:36  	at app//org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:138)
04:52:36  	at app//org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:68)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
04:52:36  	at [email protected]/java.util.ArrayList.forEach(ArrayList.java:1596)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
04:52:36  	at [email protected]/java.util.ArrayList.forEach(ArrayList.java:1596)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
04:52:36  	at app//org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
04:52:36  	at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
04:52:36  	at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
04:52:36  	at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
04:52:36  	at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
04:52:36  	at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
04:52:36  	at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
04:52:36  	at app//org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
04:52:36  	at app//org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
04:52:36  	at app//org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
04:52:36  	at app//com.sun.javatest.regtest.agent.JUnitRunner.runWithJUnitPlatform(JUnitRunner.java:142)
04:52:36  	at app//com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:95)
04:52:36  	at app//com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:61)
04:52:36  	at [email protected]/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
04:52:36  	at [email protected]/java.lang.reflect.Method.invoke(Method.java:580)
04:52:36  	at app//com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
04:52:36  	at [email protected]/java.lang.Thread.run(Thread.java:1595)
04:52:36  
04:52:36  "Finalizer thread" prio=5 Id=22 RUNNABLE
04:52:36  
04:52:36  "VirtualThread-unparker" prio=5 Id=28 WAITING
04:52:36  	at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
04:52:36  	at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
04:52:36  	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:519)
04:52:36  	at [email protected]/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3780)
04:52:36  	at [email protected]/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3725)
04:52:36  	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1707)
04:52:36  	at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1170)
04:52:36  	at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
04:52:36  	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)
04:52:36  	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
04:52:36  	at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
04:52:36  	at [email protected]/java.lang.Thread.run(Thread.java:1595)
04:52:36  	at [email protected]/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)
04:52:36  
04:52:36  "Attachment portNumber: 43467" prio=10 Id=31 RUNNABLE
04:52:36  	at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
04:52:36  	at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:249)
04:52:36  	at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:185)
04:52:36  	at [email protected]/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
04:52:36  	at [email protected]/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
04:52:36  
04:52:36  "file lock watchdog" prio=10 Id=32 TIMED_WAITING
04:52:36  	at [email protected]/java.lang.Object.waitImpl(Native Method)
04:52:36  	at [email protected]/java.lang.Object.wait(Object.java:255)
04:52:36  	at [email protected]/java.lang.Object.wait(Object.java:221)
04:52:36  	at [email protected]/java.util.TimerThread.mainLoop(Timer.java:602)
04:52:36  	at [email protected]/java.util.TimerThread.run(Timer.java:543)

Test output

04:52:36  STDOUT:
04:52:36  Timeout signalled after 960 seconds
04:52:36  STDERR:
04:52:36  STARTED    GetThreadStateTest::testTerminated 'testTerminated()'
04:52:36    expect state=0x2 (JVMTI_THREAD_STATE_TERMINATED) ...
04:52:36    thread state=0x2 (JVMTI_THREAD_STATE_TERMINATED)
04:52:36  SUCCESSFUL GetThreadStateTest::testTerminated 'testTerminated()'
04:52:36  STARTED    GetThreadStateTest::testMonitorEnter 'testMonitorEnter()'
04:52:36    await state=0x401 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_BLOCKED_ON_MONITOR_ENTER) ...
04:52:36    thread state=0x401 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_BLOCKED_ON_MONITOR_ENTER)
04:52:36    expect state=0x200401 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_BLOCKED_ON_MONITOR_ENTER | JVMTI_THREAD_STATE_INTERRUPTED) ...
04:52:36    thread state=0x200401 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_BLOCKED_ON_MONITOR_ENTER | JVMTI_THREAD_STATE_INTERRUPTED)
04:52:36  SUCCESSFUL GetThreadStateTest::testMonitorEnter 'testMonitorEnter()'
04:52:36  STARTED    GetThreadStateTest::testParkNanos 'testParkNanos()'
04:52:36    await state=0x2a1 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_WAITING | JVMTI_THREAD_STATE_WAITING_WITH_TIMEOUT | JVMTI_THREAD_STATE_PARKED) ...
04:52:36    thread state=0x2a1 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_WAITING | JVMTI_THREAD_STATE_WAITING_WITH_TIMEOUT | JVMTI_THREAD_STATE_PARKED)
04:52:36  SUCCESSFUL GetThreadStateTest::testParkNanos 'testParkNanos()'
04:52:36  STARTED    GetThreadStateTest::testPark 'testPark()'
04:52:36    await state=0x291 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_WAITING | JVMTI_THREAD_STATE_WAITING_INDEFINITELY | JVMTI_THREAD_STATE_PARKED) ...
04:52:36    thread state=0x291 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_WAITING | JVMTI_THREAD_STATE_WAITING_INDEFINITELY | JVMTI_THREAD_STATE_PARKED)
04:52:36  SUCCESSFUL GetThreadStateTest::testPark 'testPark()'
04:52:36  STARTED    GetThreadStateTest::testParkWhenPinned 'testParkWhenPinned()'
04:52:36    await state=0x291 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_WAITING | JVMTI_THREAD_STATE_WAITING_INDEFINITELY | JVMTI_THREAD_STATE_PARKED) ...
04:52:36    thread state=0x400291 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_WAITING | JVMTI_THREAD_STATE_WAITING_INDEFINITELY | JVMTI_THREAD_STATE_PARKED | JVMTI_THREAD_STATE_IN_NATIVE)
04:52:36    thread state=0x400291 (JVMTI_THREAD_STATE_ALIVE | JVMTI_THREAD_STATE_WAITING | JVMTI_THREAD_STATE_WAITING_INDEFINITELY | JVMTI_THREAD_STATE_PARKED | JVMTI_THREAD_STATE_IN_NATIVE)
<LAST LINE REPEATS TILL THE TEST TIMESOUT>
@babsingh
Copy link
Contributor Author

Fixed by #18660.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
comp:jvmti comp:vm test failure
Projects
None yet
Milestone
Java 21 (0.42)
Development

No branches or pull requests
2 participants
@babsingh @pshipton