search

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.28k stars 722 forks source link

OpenJDK java/lang/Thread/virtual/Collectable.java timeout #18463

Open pshipton opened 11 months ago

pshipton commented 11 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/96 - win2019x64-openj9-4 jdk_lang_j9_0 java/lang/Thread/virtual/Collectable.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/96/openjdk_test_output.tar.gz

20:54:55  ACTION: junit -- Error. Program `C:\Users\jenkins\workspace\Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0\jdkbinary\j2sdk-image\bin\java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 980797ms).
20:54:55  REASON: User specified action: run junit/othervm -Xjit:enableAggressiveLiveness Collectable 
20:54:55  TIME:   980.813 seconds
20:54:55  messages:
20:54:55  command: junit -Xjit:enableAggressiveLiveness Collectable
20:54:55  reason: User specified action: run junit/othervm -Xjit:enableAggressiveLiveness Collectable 
20:54:55  started: Wed Nov 15 20:38:29 EST 2023
20:54:55  Mode: othervm [/othervm specified]
20:54:55  Timeout information:
20:54:55  Running jcmd on process 1960
20:54:55  Dump written to C:\Users\jenkins\workspace\Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0\aqa-tests\TKG\output_17000937787349\jdk_lang_j9_0\work\scratch\1\core.20231115.205430.1960.0001.dmp
20:54:55  Dump written to C:\Users\jenkins\workspace\Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0\aqa-tests\TKG\output_17000937787349\jdk_lang_j9_0\work\scratch\1\javacore.20231115.205448.1960.0002.txt
20:54:55  Running jstack on process 1960
20:54:55  2023-11-15T20:54:49.048391400
20:54:55  Virtual machine: 1960 JVM information:
20:54:55  JRE 21 Windows Server 2019 amd64-64-Bit 20231115_107 (JIT enabled, AOT enabled)
20:54:55  OpenJ9   - a7076bc0e4a
20:54:55  OMR      - 07a175a4d23
20:54:55  JCL      - 4b666c7419b based on jdk-21.0.1+12
20:54:55  
20:54:55  "main" prio=5 Id=2 WAITING
20:54:55    at java.base@21.0.1-internal/java.lang.Object.waitImpl(Native Method)
20:54:55    at java.base@21.0.1-internal/java.lang.Object.wait(Object.java:255)
20:54:55    at java.base@21.0.1-internal/java.lang.Object.wait(Object.java:221)
20:54:55    at java.base@21.0.1-internal/java.lang.Thread.join(Thread.java:2105)
20:54:55    at java.base@21.0.1-internal/java.lang.Thread.join(Thread.java:2181)
20:54:55    at app//com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:85)
20:54:55  
20:54:55  "JIT Compilation Thread-000" prio=10 Id=4 RUNNABLE
20:54:55  
20:54:55  "JIT Compilation Thread-001 Suspended" prio=10 Id=5 RUNNABLE
20:54:55  
20:54:55  "JIT Compilation Thread-002 Suspended" prio=10 Id=6 RUNNABLE
20:54:55  
20:54:55  "JIT Diagnostic Compilation Thread-003 Suspended" prio=10 Id=7 RUNNABLE
20:54:55  
20:54:55  "JIT-SamplerThread" prio=10 Id=8 TIMED_WAITING
20:54:55  
20:54:55  "IProfiler" prio=5 Id=9 RUNNABLE
20:54:55  
20:54:55  "Common-Cleaner" prio=8 Id=3 TIMED_WAITING
20:54:55    at java.base@21.0.1-internal/java.lang.Object.waitImpl(Native Method)
20:54:55    at java.base@21.0.1-internal/java.lang.Object.wait(Object.java:255)
20:54:55    at java.base@21.0.1-internal/java.lang.Object.wait(Object.java:221)
20:54:55    at java.base@21.0.1-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
20:54:55    at java.base@21.0.1-internal/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
20:54:55    at java.base@21.0.1-internal/java.lang.Thread.run(Thread.java:1595)
20:54:55    at java.base@21.0.1-internal/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)
20:54:55  
20:54:55  "Dedicated GC Main" prio=5 Id=10 RUNNABLE
20:54:55  
20:54:55  "GC Worker" prio=5 Id=11 RUNNABLE
20:54:55  
20:54:55  "GC Worker" prio=5 Id=12 RUNNABLE
20:54:55  
20:54:55  "GC Worker" prio=5 Id=13 RUNNABLE
20:54:55  
20:54:55  "Attach API wait loop" prio=10 Id=16 RUNNABLE
20:54:55    at java.base@21.0.1-internal/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
20:54:55    at java.base@21.0.1-internal/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
20:54:55    at java.base@21.0.1-internal/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
20:54:55    at java.base@21.0.1-internal/openj9.internal.tools.attach.target.WaitLoop.run(WaitLoop.java:157)
20:54:55  
20:54:55  "MainThread" prio=5 Id=17 TIMED_WAITING
20:54:55    at java.base@21.0.1-internal/java.lang.Thread.sleepImpl(Native Method)
20:54:55    at java.base@21.0.1-internal/java.lang.Thread.sleep(Thread.java:516)
20:54:55    at app//Collectable.waitUntilCleared(Collectable.java:65)
20:54:55    at app//Collectable.testUnstartedThread(Collectable.java:46)
20:54:55    at java.base@21.0.1-internal/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
20:54:55    at java.base@21.0.1-internal/java.lang.reflect.Method.invoke(Method.java:580)
20:54:55    at app//org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)
20:54:55    at app//org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
20:54:55    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
20:54:55    at app//org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
20:54:55    at app//org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
20:54:55    at app//org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
20:54:55    at app//org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
20:54:55    at app//org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
20:54:55    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
20:54:55    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
20:54:55    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
20:54:55    at app//org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
20:54:55    at app//org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
20:54:55    at app//org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
20:54:55    at app//org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:217)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
20:54:55    at app//org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:213)
20:54:55    at app//org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:138)
20:54:55    at app//org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:68)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
20:54:55    at java.base@21.0.1-internal/java.util.ArrayList.forEach(ArrayList.java:1596)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
20:54:55    at java.base@21.0.1-internal/java.util.ArrayList.forEach(ArrayList.java:1596)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
20:54:55    at app//org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
20:54:55    at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
20:54:55    at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
20:54:55    at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
20:54:55    at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
20:54:55    at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
20:54:55    at app//org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
20:54:55    at app//org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
20:54:55    at app//org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
20:54:55    at app//org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
20:54:55    at app//com.sun.javatest.regtest.agent.JUnitRunner.runWithJUnitPlatform(JUnitRunner.java:142)
20:54:55    at app//com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:95)
20:54:55    at app//com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:61)
20:54:55    at java.base@21.0.1-internal/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
20:54:55    at java.base@21.0.1-internal/java.lang.reflect.Method.invoke(Method.java:580)
20:54:55    at app//com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
20:54:55    at java.base@21.0.1-internal/java.lang.Thread.run(Thread.java:1595)
20:54:55  
20:54:55  "Finalizer thread" prio=5 Id=19 RUNNABLE
20:54:55  
20:54:55  "file lock watchdog" prio=10 Id=24 TIMED_WAITING
20:54:55    at java.base@21.0.1-internal/java.lang.Object.waitImpl(Native Method)
20:54:55    at java.base@21.0.1-internal/java.lang.Object.wait(Object.java:255)
20:54:55    at java.base@21.0.1-internal/java.lang.Object.wait(Object.java:221)
20:54:55    at java.base@21.0.1-internal/java.util.TimerThread.mainLoop(Timer.java:570)
20:54:55    at java.base@21.0.1-internal/java.util.TimerThread.run(Timer.java:523)
20:54:55  
20:54:55  "Attachment portNumber: 51208" prio=10 Id=26 RUNNABLE
20:54:55    at java.base@21.0.1-internal/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
20:54:55    at java.base@21.0.1-internal/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:249)
20:54:55    at java.base@21.0.1-internal/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:185)
20:54:55    at java.base@21.0.1-internal/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
20:54:55    at java.base@21.0.1-internal/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
20:54:55  
20:54:55  
20:54:55  --- Timeout information end.
babsingh commented 11 months ago

The test creates a weak reference for an unstarted virtual thread, sets the thread variable to null, and waits till the unstarted thread is collected by the GC. The timeout happens after 960 seconds.

Test source code: Collectable.java#L46C5-L46C5


    @Test
    void testUnstartedThread() {
        var thread = Thread.ofVirtual().unstarted(() -> { });
        var ref = new WeakReference<>(thread);
        thread = null;
        waitUntilCleared(ref);
    }

    private static void waitUntilCleared(WeakReference<?> ref) {
        while (ref.get() != null) {
            System.gc();
            try {
                Thread.sleep(50);
            } catch (InterruptedException ignore) { }
        }
    }
babsingh commented 11 months ago

Behaviour similar to https://github.com/eclipse-openj9/openj9/issues/17241 is seen in this issue. #17241 was addressed by running the test with -Xjit:enableAggressiveLiveness. In this case, the virtual thread object is in an I-slot not an O-slot.

Requesting feedback from the GC team: @dmitripivkine, @LinHu2016, @amicic.

fyi @0xdaryl 

> !stackslots 0x1cfdb27e300
<1cfdb27e300> *** BEGIN STACK WALK, flags = 00400001 walkThread = 1,992,246,682,368 ***
<1cfdb27e300>   ITERATE_O_SLOTS
<1cfdb27e300>   RECORD_BYTECODE_PC_OFFSET
<1cfdb27e300> Initial values: walkSP = 0x000001CFDB374D68, PC = 0x0000000000000006, literals = 0x0000000000000000, A0 = 0x000001CFDB374DD0, j2iFrame = 0x000001CFDB375728, decomp = 0x0000000000000000
<1cfdb27e300> JIT JNI call-out frame: bp = 0x000001CFDB374D88, sp = 0x000001CFDB374D68, pc = 0x0000000000000006, cp = 0x000001CFDAF7C140, arg0EA = 0x000001CFDB374DD0, flags = 0x0000000020000000
<1cfdb27e300>   Method: java/lang/Thread.sleepImpl(JI)V !j9method 0x000001CFDAF7D5D0
<1cfdb27e300> JIT frame: bp = 0x000001CFDB374DD8, pc = 0x00007FFB3EFDEC52, unwindSP = 0x000001CFDB374D90, cp = 0x000001CFDAF7C140, arg0EA = 0x000001CFDB374DE8, jitInfo = 0x000001CFDB7FEB68
<1cfdb27e300>   Method: java/lang/Thread.sleep(J)V !j9method 0x000001CFDAF7D5B0
<1cfdb27e300>   Bytecode index = 61, inlineDepth = 0, PC offset = 0x0000000000000132
<1cfdb27e300>   stackMap=0x000001CFDB7FED46, slots=I16(0x0002) parmBaseOffset=I16(0x0018), parmSlots=U16(0x0000), localBaseOffset=I16(0xFFF0)
<1cfdb27e300>   Described JIT temps starting at 0x000001CFDB374DC8 for IDATA(0x0000000000000002) slots
<1cfdb27e300>       O-Slot: : t1[0x000001CFDB374DC8] = 0x0000000000000000
<1cfdb27e300>       O-Slot: : t0[0x000001CFDB374DD0] = 0x0000000000000000
<1cfdb27e300>   JIT-RegisterMap = UDATA(0x0000000000000000)
<1cfdb27e300>   JIT-Frame-RegisterMap[0x000001CFDB374DB0] = UDATA(0x0000000000000001) (jit_rbx)
<1cfdb27e300>   JIT-Frame-RegisterMap[0x000001CFDB374DB8] = UDATA(0x000001CFBCA2BE50) (jit_r9)
<1cfdb27e300> JIT frame: bp = 0x000001CFDB374E18, pc = 0x00007FFB3EFD46AD, unwindSP = 0x000001CFDB374DE0, cp = 0x000001CFDB355CD0, arg0EA = 0x000001CFDB374E20, jitInfo = 0x000001CFDB7F7B68
<1cfdb27e300>   Method: Collectable.waitUntilCleared(Ljava/lang/ref/WeakReference;)V !j9method 0x000001CFDB355EE8
<1cfdb27e300>   Bytecode index = 13, inlineDepth = 0, PC offset = 0xFFFFFFFFFFFF898D
<1cfdb27e300>   stackMap=0x000001CFDB7F7CB8, slots=I16(0x0001) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0001), localBaseOffset=I16(0xFFE8)
<1cfdb27e300>   Described JIT args starting at 0x000001CFDB374E20 for U16(0x0001) slots
<1cfdb27e300>       O-Slot: : a0[0x000001CFDB374E20] = 0x00007FF48F8D4900 <--- // WeakReference
<1cfdb27e300>   Described JIT temps starting at 0x000001CFDB374E00 for IDATA(0x0000000000000003) slots
<1cfdb27e300>       I-Slot: : t2[0x000001CFDB374E00] = 0x00007FF48F8D4770 <--- // VirtualThread
<1cfdb27e300>       I-Slot: : t1[0x000001CFDB374E08] = 0x00007FFB531700D0
<1cfdb27e300>       I-Slot: : t0[0x000001CFDB374E10] = 0x00007FF48FCA11F8
<1cfdb27e300>   JIT-RegisterMap = UDATA(0x0000000000000000)
<1cfdb27e300>   JIT-Frame-RegisterMap[0x000001CFDB374DB0] = UDATA(0x0000000000000001) (jit_rbx)
<1cfdb27e300>   JIT-Frame-RegisterMap[0x000001CFDB374DB8] = UDATA(0x000001CFBCA2BE50) (jit_r9)
<1cfdb27e300> I2J values: PC = 0x000001CFDB337756, A0 = 0x000001CFDB374E58, walkSP = 0x000001CFDB374E30, literals = 0x000001CFDB355EA8, JIT PC = 0x00007FFB531700D0, pcAddress = 0x0000005A08C7F628, decomp = 0x0000000000000000
<1cfdb27e300> Bytecode frame: bp = 0x000001CFDB374E40, sp = 0x000001CFDB374E30, pc = 0x000001CFDB337756, cp = 0x000001CFDB355CD0, arg0EA = 0x000001CFDB374E58, flags = 0x0000000000000000
<1cfdb27e300>   Method: Collectable.testUnstartedThread()V !j9method 0x000001CFDB355EA8
<1cfdb27e300>   Bytecode index = 26
<1cfdb27e300>   Using local mapper
<1cfdb27e300>   Locals starting at 0x000001CFDB374E58 for 0x0000000000000003 slots
<1cfdb27e300>       I-Slot: a0[0x000001CFDB374E58] = 0x00007FF48FC974B8
<1cfdb27e300>       I-Slot: t1[0x000001CFDB374E50] = 0x0000000000000000
<1cfdb27e300>       I-Slot: t2[0x000001CFDB374E48] = 0x00007FF48FCA1388
dmitripivkine commented 11 months ago

looking briefly to the core... Weak Reference !j9object 0x00007FF48F8D4900 VirtualThread !j9object 0x7ff48f8d4770 marked (alive)

Referenced from:

> !findall u64 0x00007FF48F8D4770
Scanning memory for 70 47 8d 8f f4 7f 00 00 aligned to 8 starting from 0x0
Match found at 0x1cfdb374e00        I-Slot: : t2[0x000001CFDB374E00] = 0x00007FF48F8D4770 <-- does not keep alive
Match found at 0x7ff48f8d4898       VirtualThread$VThreadContinuation -> vthread <-- alive
Match found at 0x7ff48f8d48d8       VirtualThread$VThreadContinuation$1 -> val$vthread <-- alive
Match found at 0x7ff48f8d48f8       VirtualThread$$Lambda/0x00000000dbca9ef0 -> arg$1 <-- alive
Match found at 0x7ff48f8d4918       WeakReference -> referent <-- does not keep alive
No more matches

Please let me know if you need more digging results.

babsingh commented 11 months ago

Why are they not being collected? All three can be collected if the virtual thread has no more references. The objects below are internal to the VirtualThread class.

Match found at 0x7ff48f8d4898       VirtualThread$VThreadContinuation -> vthread <-- alive
Match found at 0x7ff48f8d48d8       VirtualThread$VThreadContinuation$1 -> val$vthread <-- alive
Match found at 0x7ff48f8d48f8       VirtualThread$$Lambda/0x00000000dbca9ef0 -> arg$1 <-- alive
babsingh commented 11 months ago

Launched grinders to see if this issue is a blocker for the 0.42 release:

No failures are seen in the above grinders. Moving this issue to the 0.44 release due to low occurrence.

dmitripivkine commented 11 months ago

@babsingh Would you please double check somehow that 0x000001CFDB374E00 is an I-slot as reported by my DDR and not reported to GC as a root? (have suspicion in correctness of DDR reporting due failures in stack walk).

<1cfdb27e300> JIT frame: bp = 0x000001CFDB374E18, pc = 0x00007FFB3EFD46AD, unwindSP = 0x000001CFDB374DE0, cp = 0x000001CFDB355CD0, arg0EA = 0x000001CFDB374E20, jitInfo = 0x000001CFDB7F7B68
<1cfdb27e300>   Method: Collectable.waitUntilCleared(Ljava/lang/ref/WeakReference;)V !j9method 0x000001CFDB355EE8
<1cfdb27e300>   Bytecode index = 13, inlineDepth = 0, PC offset = 0xFFFFFFFFFFFF898D
<1cfdb27e300>   stackMap=0x000001CFDB7F7CB8, slots=I16(0x0001) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0001), localBaseOffset=I16(0xFFE8)
<1cfdb27e300>   Described JIT args starting at 0x000001CFDB374E20 for U16(0x0001) slots
<1cfdb27e300>       O-Slot: : a0[0x000001CFDB374E20] = 0x00007FF48F8D4900
<1cfdb27e300>   Described JIT temps starting at 0x000001CFDB374E00 for IDATA(0x0000000000000003) slots
<1cfdb27e300>       I-Slot: : t2[0x000001CFDB374E00] = 0x00007FF48F8D4770 <----
<1cfdb27e300>       I-Slot: : t1[0x000001CFDB374E08] = 0x00007FFB531700D0
<1cfdb27e300>       I-Slot: : t0[0x000001CFDB374E10] = 0x00007FF48FCA11F8
<1cfdb27e300>   JIT-RegisterMap = UDATA(0x0000000000000000)
<1cfdb27e300>   JIT-Frame-RegisterMap[0x000001CFDB374DB0] = UDATA(0x0000000000000001) (jit_rbx)
<1cfdb27e300>   JIT-Frame-RegisterMap[0x000001CFDB374DB8] = UDATA(0x000001CFBCA2BE50) (jit_r9)

Except this I-slot looks like there is only pointer to this isolated objects group is GC continuation list. I am still looking to possible problems in Balanced related to continuation list processing or handling of Weak Ref.

babsingh commented 11 months ago

@dmitripivkine For the I-slot, DDR doesn't find a root for me as well. All the DDR cmds to find the root throw the below exception because they expect an object address not an I-slot address.

> !anyrootpathfindall 0x000001CFDB374E00
Problem running command:
DDRInteractiveCommandException: object class is not valid (eyecatcher is not 0x99669966)
    at RootPathCommand.run(RootPathCommand.java:264)
        ...

<1cfdb27e300>       I-Slot: : t2[0x000001CFDB374E00] = 0x00007FF48F8D4770

> !j9object 0x00007FF48F8D4770
!J9Object 0x00007FF48F8D4770 {
    struct J9Class* clazz = !j9class 0x1CFDAF9CE00 // java/lang/VirtualThread

> !j9class 0x1CFDAF9CE00
J9Class at 0x1cfdaf9ce00 {
  Fields for J9Class:
    0x0: U64 eyecatcher = 0x0000000099669966 (2573637990) <--- GOOD
babsingh commented 11 months ago

DDR finds the root for the virtual thread address, but it also detects corruption on my end. With rootpathverbose, I see the below exception, which reports Operand stack underflow in StackMap. @dmitripivkine Is the corruption relevant to this issue or just another DDR bug?

> !anyrootpathfindall 0x00007FF48F8D4770
Nov 21, 2023 7:08:23 PM com.ibm.j9ddr.vm29.events.DefaultEventListener corruptData
WARNING: CorruptData encountered iterating o-slots. walkThread = 0x000001CFDB27E300
com.ibm.j9ddr.CorruptDataException: Operand stack underflow in StackMap
    at com.ibm.j9ddr.vm29.j9.stackmap.StackMap$J9MappingStack.POP(StackMap.java:184)
    at com.ibm.j9ddr.vm29.j9.stackmap.StackMap$StackMap_V1.POP(StackMap.java:692)
    at com.ibm.j9ddr.vm29.j9.stackmap.StackMap$StackMap_V1.mapStack(StackMap.java:573)
    at com.ibm.j9ddr.vm29.j9.stackmap.StackMap$StackMap_V1.j9stackmap_StackBitsForPC(StackMap.java:270)
    at com.ibm.j9ddr.vm29.j9.stackmap.StackMap.j9stackmap_StackBitsForPC(StackMap.java:106)
    at com.ibm.j9ddr.vm29.j9.stackwalker.StackWalker$StackWalker_29_V0.getStackMap(StackWalker.java:1053)
    at com.ibm.j9ddr.vm29.j9.stackwalker.StackWalker$StackWalker_29_V0.walkBytecodeFrameSlots(StackWalker.java:952)
    at com.ibm.j9ddr.vm29.j9.stackwalker.StackWalker$StackWalker_29_V0.walkBytecodeFrame(StackWalker.java:1036)
    at com.ibm.j9ddr.vm29.j9.stackwalker.StackWalker$StackWalker_29_V0.commonWalker(StackWalker.java:478)
    at com.ibm.j9ddr.vm29.j9.stackwalker.StackWalker$StackWalker_29_V0.walkStackFrames(StackWalker.java:196)
    at com.ibm.j9ddr.vm29.j9.stackwalker.StackWalker.walkStackFrames(StackWalker.java:99)
    at com.ibm.j9ddr.vm29.j9.GCVMThreadStackSlotIterator.scanSlots(GCVMThreadStackSlotIterator.java:59)
    at com.ibm.j9ddr.vm29.j9.RootScanner.scanThreads(RootScanner.java:701)
    at com.ibm.j9ddr.vm29.j9.RootScanner.scanAllSlots(RootScanner.java:362)
    ...

========================================
java/lang/ref/WeakReference@0x00007FF48F8D4900
  java/lang/VirtualThread@0x00007FF48F8D4770
Corruption detected walking live set
dmitripivkine commented 11 months ago

I think corruption is not relevant to the original problem, just another DDR stack walker issue. Also please note DDR root search commands treat Weak References as hard roots mistakenly.

pshipton commented 11 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/100/

dmitripivkine commented 11 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/100/

There is no stored artifacts unfortunately. And yes, this is Balanced again.

pshipton commented 9 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/137 jdk_lang_0 java/lang/Thread/virtual/Collectable.java - timeout

pshipton commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OMR_testList_0/74 jdk_lang_0 java/lang/Thread/virtual/Collectable.java - timeout

dmitripivkine commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OMR_testList_0/74 jdk_lang_0 java/lang/Thread/virtual/Collectable.java - timeout

The problem is for Weak Reference !j9object 0x000000002E067720 it's referent Virtual Thread object !fj9object 0x2e067618 is stored in O-slot and can not be collected obviously:

<1cac200> JIT frame: bp = 0x0000000001CB1348, pc = 0x000003FF892AE474, unwindSP = 0x0000000001CB1308, cp = 0x0000000001C9D4D0, arg0EA = 0x0000000001CB1350, jitInfo = 0x000003FF82CF2DF8
<1cac200>   Method: Collectable.waitUntilCleared(Ljava/lang/ref/WeakReference;)V !j9method 0x0000000001C9D6E8
<1cac200>   Bytecode index = 7, inlineDepth = 0, PC offset = 0xFFFFFFFFFFF61D7A
<1cac200>   stackMap=0x000003FF82CF2F39, slots=I16(0x0001) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0001), localBaseOffset=I16(0xFFE8)
<1cac200>   Described JIT args starting at 0x0000000001CB1350 for U16(0x0001) slots
<1cac200>       O-Slot: : a0[0x0000000001CB1350] = 0x000000002E067720 <----- Weak Reference
<1cac200>   Described JIT temps starting at 0x0000000001CB1330 for IDATA(0x0000000000000003) slots
<1cac200>       O-Slot: : t2[0x0000000001CB1330] = 0x000000002E067618 <----- VT object is stored in O-slot
<1cac200>       I-Slot: : t1[0x0000000001CB1338] = 0x000003FFA3C90950
<1cac200>       I-Slot: : t0[0x0000000001CB1340] = 0x000000002E0DB948
<1cac200>   JIT-RegisterMap = UDATA(0x0000000000000000)
<1cac200>   JIT-Frame-RegisterMap[0x0000000001CB12B8] = UDATA(0x000000000E301FB8) (jit_r6)
<1cac200>   JIT-Frame-RegisterMap[0x0000000001CB12C0] = UDATA(0x0000000001AE2600) (jit_r7)
<1cac200>   JIT-Frame-RegisterMap[0x0000000001CB12C8] = UDATA(0x0000000001AE2600) (jit_r8)
<1cac200>   JIT-Frame-RegisterMap[0x0000000001CB12D0] = UDATA(0x0000000000000000) (jit_r9)
<1cac200>   JIT-Frame-RegisterMap[0x0000000001CB12D8] = UDATA(0x0000000000000000) (jit_r10)
<1cac200>   JIT-Frame-RegisterMap[0x0000000001CB12E0] = UDATA(0x000000002E0DA1A8) (jit_r11)
<1cac200>   JIT-Frame-RegisterMap[0x0000000001CB12E8] = UDATA(0x000000002E04A3D8) (jit_r12)
dmitripivkine commented 8 months ago

@hzongaro I guess this is manifestation of optimization can be disabled by -Xjit:enableAggressiveLiveness. This problem start happened often. I am not sure it is because of hotness of the method. So, passing this item to JIT for conclusion.

dmitripivkine commented 8 months ago

The mystery is for very first failure with Balanced GC Virtual Thread object is stored in I-slot:

<1cfdb27e300> JIT frame: bp = 0x000001CFDB374E18, pc = 0x00007FFB3EFD46AD, unwindSP = 0x000001CFDB374DE0, cp = 0x000001CFDB355CD0, arg0EA = 0x000001CFDB374E20, jitInfo = 0x000001CFDB7F7B68
<1cfdb27e300>   Method: Collectable.waitUntilCleared(Ljava/lang/ref/WeakReference;)V !j9method 0x000001CFDB355EE8
<1cfdb27e300>   Bytecode index = 13, inlineDepth = 0, PC offset = 0xFFFFFFFFFFFF898D
<1cfdb27e300>   stackMap=0x000001CFDB7F7CB8, slots=I16(0x0001) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0001), localBaseOffset=I16(0xFFE8)
<1cfdb27e300>   Described JIT args starting at 0x000001CFDB374E20 for U16(0x0001) slots
<1cfdb27e300>       O-Slot: : a0[0x000001CFDB374E20] = 0x00007FF48F8D4900 <--- Weak Reference object
<1cfdb27e300>   Described JIT temps starting at 0x000001CFDB374E00 for IDATA(0x0000000000000003) slots
<1cfdb27e300>       I-Slot: : t2[0x000001CFDB374E00] = 0x00007FF48F8D4770 <--- Virtual Thread object
<1cfdb27e300>       I-Slot: : t1[0x000001CFDB374E08] = 0x00007FFB531700D0
<1cfdb27e300>       I-Slot: : t0[0x000001CFDB374E10] = 0x00007FF48FCA11F8
<1cfdb27e300>   JIT-RegisterMap = UDATA(0x0000000000000000)
<1cfdb27e300>   JIT-Frame-RegisterMap[0x000001CFDB374DB0] = UDATA(0x0000000000000001) (jit_rbx)
<1cfdb27e300>   JIT-Frame-RegisterMap[0x000001CFDB374DB8] = UDATA(0x000001CFBCA2BE50) (jit_r9)

I can not find another root to this object, but it survived thousands of GCs, so, discovered alive somehow. GC relies on JIT frame slot iterator . Is it possible this I-slot is reported to GC (by some internal JIT reason) and treated as a hard root?

babsingh commented 8 months ago

I guess this is manifestation of optimization can be disabled by -Xjit:enableAggressiveLiveness

In our JDK21+ builds, we run the test with -Xjit:enableAggressiveLiveness: Collectable.java#L27. I have verified that -Xjit:enableAggressiveLiveness is applied in the build log: https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OMR_testList_0/74.

hzongaro commented 8 months ago

@BradleyWood, may I ask you to help look at this problem? I haven't looked at this in any detail, but I'm wondering whether the more expensive liveness analysis proposed in issue #16686 is something that would help here.

JasonFengJ9 commented 8 months ago

JDK22 x86-64_linux

19:35:47  variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode150
19:35:47  JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:+UseCompressedOops -Xverbosegclog 

20:09:52  TEST: java/lang/Thread/virtual/Collectable.java

20:09:52  TEST RESULT: Error. Program `/home/jenkins/workspace/Test_openjdk22_j9_sanity.openjdk_x86-64_linux_Personal_testList_0/jdkbinary/j2sdk-image/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 964173ms).
20:09:52  --------------------------------------------------
20:09:52  Test results: passed: 933; error: 1
20:10:10  Report written to /home/jenkins/workspace/Test_openjdk22_j9_sanity.openjdk_x86-64_linux_Personal_testList_0/aqa-tests/TKG/output_1708648546575/jdk_lang_0/report/html/report.html
20:10:10  Results written to /home/jenkins/workspace/Test_openjdk22_j9_sanity.openjdk_x86-64_linux_Personal_testList_0/aqa-tests/TKG/output_1708648546575/jdk_lang_0/work
20:10:10  Error: Some tests failed or other problems occurred.
20:10:10  -----------------------------------
20:10:10  jdk_lang_0_FAILED
pshipton commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/164 - timeout jdk_lang_j9_0 java/lang/Thread/virtual/Collectable.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/164/openjdk_test_output.tar.gz

23:30:49  "MainThread" prio=5 Id=17 TIMED_WAITING
23:30:49    at java.base@21.0.3-internal/java.lang.Thread.sleepImpl(Native Method)
23:30:49    at java.base@21.0.3-internal/java.lang.Thread.sleep(Thread.java:516)
23:30:49    at app//Collectable.waitUntilCleared(Collectable.java:65)
23:30:49    at app//Collectable.testUnstartedThread(Collectable.java:46)
pshipton commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_mac_Nightly_testList_1/122

pshipton commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_ppc64le_linux_OMR_testList_0/39/

vij-singh commented 8 months ago

@BradleyWood Any updates on this one?

dmitripivkine commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_ppc64le_linux_OMR_testList_0/39/

This is another failure with Balanced with stored core. It is not clear how VT object is reachable. The only speculation the I-slot pointed to it is reported by JIT as an O-slot (???). Please note with Gencon this slot actually is an O-slot. I suggest to complete JIT investigation for Gencon (it is easy reproducible case) and fix the problem. Later on we can check is Balanced case happens to be fixed as well.

pshipton commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_1/168/

dmitripivkine commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_1/168/

Interesting. This is case VT object is stored in I-slot and this is Gencon. I will take a closer look.

dmitripivkine commented 8 months ago

Interesting. This is case VT object is stored in I-slot and this is Gencon. I will take a closer look.

System GC discovers VT object alive indeed. This is Gencon, so, there is no complication related to Balanced. I have inspected all occurrences of the pointer to VT object across the core including native code. (Please let me know if you need see details) I can not find any roots for this object. The only suspicion I have can JIT return this object address from JIT Frame Iterator to GC despite DDR sees it as an I-slot?

hzongaro commented 8 months ago

@BradleyWood, could you take a look at @dmitripivkine's recent suspicions?

BradleyWood commented 8 months ago

I haven't been able to reproduce the test case locally, even without enableAggressiveLiveness

pshipton commented 7 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_Nightly_testList_1/183/

pshipton commented 7 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_Nightly_testList_1/130 https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Release_testList_0/11 https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_Nightly_testList_0/134 https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/183/ https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.openjdk_aarch64_linux_Nightly_testList_1/41/ https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.openjdk_aarch64_linux_Nightly_testList_0/42/ https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_Nightly_testList_1/198/ https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/46/ https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_Nightly_testList_1/203/ https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.openjdk_x86-64_linux_Nightly_testList_0/46/

vij-singh commented 7 months ago

@BradleyWood Reminder to add a comment with current status including next steps

BradleyWood commented 7 months ago

I haven't forgotten about this issue. I am still not able to reproduce the issue locally. I need to look into why the JIT put the object into an o-slot despite enableAggressiveLiveness.

dmitripivkine commented 7 months ago

There is another item https://github.com/eclipse-openj9/openj9/issues/9651 This problem looks similar - JIT stores object pointer in O-slot despite enableAggressiveLiveness and it can not be collected as expected by test. I am not sure is it easier to use for reproduction, it is intermittent as well.

pshipton commented 6 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdknext_j9_sanity.openjdk_ppc64le_linux_Nightly_testList_0/2

dmitripivkine commented 6 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdknext_j9_sanity.openjdk_ppc64le_linux_Nightly_testList_0/2

GC policy: Gencon -Xjit:enableAggressiveLiveness is set. Weak Reference !j9object 0x00000000FFDEBE90 Virtual thread object !j9object 0x00000000FFDEBD88 is stored in the O-slot, so it can not be collected

<29ca00> JIT frame: bp = 0x00000000002A1A68, pc = 0x000071B6060B5F70, unwindSP = 0x00000000002A1A30, cp = 0x0000000000285CD0, arg0EA = 0x00000000002A1A70, jitInfo = 0x000071B5E7D50F78
<29ca00>    Method: Collectable.waitUntilCleared(Ljava/lang/ref/WeakReference;)V !j9method 0x0000000000285EE8
<29ca00>    Bytecode index = 7, inlineDepth = 0, PC offset = 0xFFFFFFFFFFFED074
<29ca00>    stackMap=0x000071B5E7D510B9, slots=I16(0x0001) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0001), localBaseOffset=I16(0xFFE8)
<29ca00>    Described JIT args starting at 0x00000000002A1A70 for U16(0x0001) slots
<29ca00>        O-Slot: : a0[0x00000000002A1A70] = 0x00000000FFDEBE90
<29ca00>    Described JIT temps starting at 0x00000000002A1A50 for IDATA(0x0000000000000003) slots
<29ca00>        O-Slot: : t2[0x00000000002A1A50] = 0x00000000FFDEBD88 <---
<29ca00>        I-Slot: : t1[0x00000000002A1A58] = 0x000071B625B61B10
<29ca00>        I-Slot: : t0[0x00000000002A1A60] = 0x00000000FFE5FE70
pshipton commented 6 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/211 - win2012-x86-1a https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_OpenJDK21_testList_0/22 - ub20-aarch64-osu-1 https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_1/217/ - win2019x64-openj9-3 https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_Release_testList_1/20 - ub18-x86-1a https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/235 - win2019x64-openj9-4a https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_Nightly_testList_1/165/ - ub16x64j96

JasonFengJ9 commented 5 months ago

JDK23 ppc64le_linux(ubu20le-rtp-rt1-1)

17:01:23  variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode501
17:01:23  JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -Xjit -Xgcpolicy:balanced -Xnocompressedrefs -Xverbosegclog 

17:41:52  TEST: java/lang/Thread/virtual/Collectable.java

17:41:52  TEST RESULT: Error. Program `/home/jenkins/workspace/Test_openjdknext_j9_sanity.openjdk_ppc64le_linux_Personal_testList_0/jdkbinary/j2sdk-image/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 965154ms).
17:41:52  --------------------------------------------------
17:41:52  Test results: passed: 930; error: 1
17:42:16  Report written to /home/jenkins/workspace/Test_openjdknext_j9_sanity.openjdk_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_17152869117629/jdk_lang_j9_0/report/html/report.html
17:42:16  Results written to /home/jenkins/workspace/Test_openjdknext_j9_sanity.openjdk_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_17152869117629/jdk_lang_j9_0/work
17:42:16  Error: Some tests failed or other problems occurred.
17:42:16  -----------------------------------
17:42:16  jdk_lang_j9_0_FAILED
dmitripivkine commented 5 months ago

This item is on JIT side. However as I understand there is no luck to reproduce it reliable. Moving it to the next milestone.

pshipton commented 2 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_OMR_testList_1/153

pshipton commented 2 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_OpenJDK21_testList_1/28 https://openj9-jenkins.osuosl.org/job/Test_openjdk23_j9_sanity.openjdk_x86-64_linux_Nightly_testList_1/41

JasonFengJ9 commented 2 months ago

JDK21 x86-64_linux 0.46.1(ubu22x86-svl-rt11-1)

[2024-09-05T15:40:10.517Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode150
[2024-09-05T15:40:10.517Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:+UseCompressedOops -Xverbosegclog 

[2024-09-05T16:15:43.080Z] TEST: java/lang/Thread/virtual/Collectable.java

[2024-09-05T16:15:43.082Z] TEST RESULT: Error. Program `/home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_testList_1/jdkbinary/j2sdk-image/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 966700ms).
[2024-09-05T16:15:43.082Z] --------------------------------------------------
[2024-09-05T16:15:43.082Z] Test results: passed: 937; error: 1
[2024-09-05T16:16:16.527Z] Report written to /home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_testList_1/aqa-tests/TKG/output_17255508092237/jdk_lang_0/report/html/report.html
[2024-09-05T16:16:16.527Z] Results written to /home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_testList_1/aqa-tests/TKG/output_17255508092237/jdk_lang_0/work
[2024-09-05T16:16:16.527Z] Error: Some tests failed or other problems occurred.
[2024-09-05T16:16:16.527Z] -----------------------------------
[2024-09-05T16:16:16.527Z] jdk_lang_0_FAILED
pshipton commented 1 month ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Nightly_testList_0/321/

JasonFengJ9 commented 3 weeks ago

openjdk23_j9_sanity.openjdk_ppc64le_linux(ubu20le-rtp-rt5-1)

[2024-10-10T01:44:55.366Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode650
[2024-10-10T01:44:55.366Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:-UseCompressedOops -Xverbosegclog 

[2024-10-10T02:22:53.320Z] TEST: java/lang/Thread/virtual/Collectable.java

[2024-10-10T02:22:53.331Z] TEST RESULT: Error. Program `/home/jenkins/workspace/Test_openjdk23_j9_sanity.openjdk_ppc64le_linux_testList_1/jdkbinary/j2sdk-image/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 965016ms).
[2024-10-10T02:22:53.331Z] --------------------------------------------------
[2024-10-10T02:22:53.331Z] Test results: passed: 932; error: 1
[2024-10-10T02:23:20.868Z] Report written to /home/jenkins/workspace/Test_openjdk23_j9_sanity.openjdk_ppc64le_linux_testList_1/aqa-tests/TKG/output_17285246938558/jdk_lang_1/report/html/report.html
[2024-10-10T02:23:20.868Z] Results written to /home/jenkins/workspace/Test_openjdk23_j9_sanity.openjdk_ppc64le_linux_testList_1/aqa-tests/TKG/output_17285246938558/jdk_lang_1/work
[2024-10-10T02:23:20.868Z] Error: Some tests failed or other problems occurred.
[2024-10-10T02:23:20.868Z] -----------------------------------
[2024-10-10T02:23:20.868Z] jdk_lang_1_FAILED
pshipton commented 3 weeks ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_Nightly_testList_0/325/

pshipton commented 2 weeks ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/259

pshipton commented 15 hours ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_OpenJDK21_testList_0/28