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.

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

JDK19 java/lang/Thread/virtual/stress/PinALot.java#id0 IllegalMonitorStateException - RuntimeException: count = 653974 #16258

Closed
JasonFengJ9 opened this issue Nov 3, 2022 · 64 comments
Assignees
Labels
comp:jit jdk19 project:loom Used to track Project Loom related work test failure
Milestone

Comments

@JasonFengJ9
Copy link
Member

JasonFengJ9 commented Nov 3, 2022

Failure link

From an internal build(rhel8le-rt1-4):

openjdk version "19.0.1-beta" 2022-10-18
IBM Semeru Runtime Open Edition 19.0.1+10-202211030535 (build 19.0.1-beta+10-202211030535)
Eclipse OpenJ9 VM 19.0.1+10-202211030535 (build master-a31c79403, JRE 19 Linux ppc64le-64-Bit Compressed References 20221103_70 (JIT enabled, AOT enabled)
OpenJ9   - a31c79403
OMR      - fc60df565
JCL      - 165f4c2690 based on jdk-19.0.1+10)

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

Optional info

Failure output (captured from console output)

[2022-11-03T06:27:44.683Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode150
[2022-11-03T06:27:44.683Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:+UseCompressedOops 

[2022-11-03T06:58:37.258Z] TEST: java/lang/Thread/virtual/stress/PinALot.java#id0

[2022-11-03T06:58:37.258Z] STDERR:
[2022-11-03T06:58:37.258Z] Exception in thread "" java.lang.IllegalMonitorStateException
[2022-11-03T06:58:37.258Z] 	at java.base/java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:175)
[2022-11-03T06:58:37.258Z] 	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1007)
[2022-11-03T06:58:37.258Z] 	at java.base/java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:494)
[2022-11-03T06:58:37.258Z] 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.remove(ScheduledThreadPoolExecutor.java:1063)
[2022-11-03T06:58:37.258Z] 	at java.base/java.util.concurrent.ThreadPoolExecutor.remove(ThreadPoolExecutor.java:1777)
[2022-11-03T06:58:37.258Z] 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.cancel(ScheduledThreadPoolExecutor.java:293)
[2022-11-03T06:58:37.258Z] 	at java.base/java.lang.VirtualThread.cancel(VirtualThread.java:611)
[2022-11-03T06:58:37.258Z] 	at java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:541)
[2022-11-03T06:58:37.258Z] 	at java.base/java.lang.Access.parkVirtualThread(Access.java:502)
[2022-11-03T06:58:37.258Z] 	at java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
[2022-11-03T06:58:37.258Z] 	at java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
[2022-11-03T06:58:37.258Z] 	at PinALot.lambda$main$0(PinALot.java:60)
[2022-11-03T06:58:37.258Z] 	at java.base/java.lang.VirtualThread.run(VirtualThread.java:292)
[2022-11-03T06:58:37.258Z] 	at java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
[2022-11-03T06:58:37.258Z] 	at java.base/jdk.internal.vm.Continuation.execute(Continuation.java:171)
[2022-11-03T06:58:37.258Z] java.lang.RuntimeException: count = 653974
[2022-11-03T06:58:37.258Z] 	at PinALot.main(PinALot.java:73)
[2022-11-03T06:58:37.258Z] 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
[2022-11-03T06:58:37.258Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
[2022-11-03T06:58:37.258Z] 	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
[2022-11-03T06:58:37.258Z] 	at java.base/java.lang.Thread.run(Thread.java:1573)
[2022-11-03T06:58:37.258Z] 
[2022-11-03T06:58:37.258Z] JavaTest Message: Test threw exception: java.lang.RuntimeException: count = 653974

[2022-11-03T06:58:37.259Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: count = 653974
[2022-11-03T06:58:37.259Z] --------------------------------------------------
[2022-11-03T07:03:24.593Z] Test results: passed: 845; failed: 1
[2022-11-03T07:03:57.879Z] Report written to /home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_testList_0/aqa-tests/TKG/output_16674568639805/jdk_lang_0/report/html/report.html
[2022-11-03T07:03:57.879Z] Results written to /home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_testList_0/aqa-tests/TKG/output_16674568639805/jdk_lang_0/work
[2022-11-03T07:03:57.879Z] Error: Some tests failed or other problems occurred.
[2022-11-03T07:03:57.879Z] 
[2022-11-03T07:03:57.879Z] jdk_lang_0_FAILED

50x internal grinder - 18/100 failed

@JasonFengJ9 JasonFengJ9 added test failure project:loom Used to track Project Loom related work jdk19 labels Nov 3, 2022
@pshipton pshipton added this to the Java 19 milestone Nov 3, 2022
@pshipton
Copy link
Member

pshipton commented Nov 4, 2022

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_Nightly/41/
jdk_lang_0
https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/43
jdk_lang_1
java/lang/Thread/virtual/stress/PinALot.java#id0

21:51:36  Exception in thread "" java.lang.IllegalMonitorStateException
21:51:36  	at java.base/java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:175)
21:51:36  	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1007)
21:51:36  	at java.base/java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:494)
21:51:36  	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.remove(ScheduledThreadPoolExecutor.java:1063)
21:51:36  	at java.base/java.util.concurrent.ThreadPoolExecutor.remove(ThreadPoolExecutor.java:1777)
21:51:36  	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.cancel(ScheduledThreadPoolExecutor.java:293)
21:51:36  	at java.base/java.lang.VirtualThread.cancel(VirtualThread.java:611)
21:51:36  	at java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:541)
21:51:36  	at java.base/java.lang.Access.parkVirtualThread(Access.java:502)
21:51:36  	at java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
21:51:36  	at java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
21:51:36  	at PinALot.lambda$main$0(PinALot.java:60)
21:51:36  	at java.base/java.lang.VirtualThread.run(VirtualThread.java:292)
21:51:36  	at java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
21:51:36  	at java.base/jdk.internal.vm.Continuation.execute(Continuation.java:171)
21:51:36  java.lang.RuntimeException: count = 851595
21:51:36  	at PinALot.main(PinALot.java:73)
21:51:36  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
21:51:36  	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
21:51:36  	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
21:51:36  	at java.base/java.lang.Thread.run(Thread.java:1573)

@pshipton
Copy link
Member

pshipton commented Nov 4, 2022

@tajila @fengxue-IS fyi. I assume a recent regression, or a test recently unexcluded.

@tajila
Copy link
Contributor

tajila commented Nov 4, 2022

20x grinder on ppc: https://openj9-jenkins.osuosl.org/job/Grinder/1502/
The grinder failed 4 times, due to #16259

@pshipton
Copy link
Member

pshipton commented Nov 7, 2022

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/44

20:57:16  STDERR:
20:57:16  Exception in thread "" java.lang.IllegalMonitorStateException
20:57:16  	at java.base/java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:175)
20:57:16  	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1007)
20:57:16  	at java.base/java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:494)
20:57:16  	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.remove(ScheduledThreadPoolExecutor.java:1063)
20:57:16  	at java.base/java.util.concurrent.ThreadPoolExecutor.remove(ThreadPoolExecutor.java:1777)
20:57:16  	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.cancel(ScheduledThreadPoolExecutor.java:293)
20:57:16  	at java.base/java.lang.VirtualThread.cancel(VirtualThread.java:611)
20:57:16  	at java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:541)
20:57:16  	at java.base/java.lang.Access.parkVirtualThread(Access.java:502)
20:57:16  	at java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
20:57:16  	at java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
20:57:16  	at PinALot.lambda$main$0(PinALot.java:60)
20:57:16  	at java.base/java.lang.VirtualThread.run(VirtualThread.java:292)
20:57:16  	at java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
20:57:16  	at java.base/jdk.internal.vm.Continuation.execute(Continuation.java:171)
20:57:16  java.lang.RuntimeException: count = 768366
20:57:16  	at PinALot.main(PinALot.java:73)
20:57:16  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
20:57:16  	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
20:57:16  	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
20:57:16  	at java.base/java.lang.Thread.run(Thread.java:1573)

@tajila
Copy link
Contributor

tajila commented Nov 7, 2022

20x grinder on aarch64: https://openj9-jenkins.osuosl.org/job/Grinder/1503/

@tajila
Copy link
Contributor

tajila commented Nov 7, 2022

I ran a grinder internally with a minor modification to ReentrantLock and I cant reproduce the failure.

@tajila
Copy link
Contributor

tajila commented Nov 8, 2022

The issue occurs when the carrier thread is set as the owner of the lock instead of the virtual thread. Investigating why this occurs

@dmitripivkine
Copy link
Contributor

dmitripivkine commented Nov 8, 2022

The issue occurs when the carrier thread is set as the owner of the lock instead of the virtual thread. Investigating why this occurs

Interesting... crash in Scavenger #16249 I am still investigating bad (stale?) object in Nursery might be taken from java/lang/VirtualThread->carrierThread

@pshipton
Copy link
Member

pshipton commented Nov 8, 2022

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_Nightly/44
jdk_lang_1
java/lang/Thread/virtual/stress/PinALot.java#id0

23:39:00  Exception in thread "" java.lang.IllegalMonitorStateException
23:39:00  	at java.base/java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:175)
23:39:00  	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1007)
23:39:00  	at java.base/java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:494)
23:39:00  	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.remove(ScheduledThreadPoolExecutor.java:1063)
23:39:00  	at java.base/java.util.concurrent.ThreadPoolExecutor.remove(ThreadPoolExecutor.java:1777)
23:39:00  	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.cancel(ScheduledThreadPoolExecutor.java:293)
23:39:00  	at java.base/java.lang.VirtualThread.cancel(VirtualThread.java:611)
23:39:00  	at java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:541)
23:39:00  	at java.base/java.lang.Access.parkVirtualThread(Access.java:502)
23:39:00  	at java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
23:39:00  	at java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
23:39:00  	at PinALot.lambda$main$0(PinALot.java:60)
23:39:00  	at java.base/java.lang.VirtualThread.run(VirtualThread.java:292)
23:39:00  	at java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
23:39:00  	at java.base/jdk.internal.vm.Continuation.execute(Continuation.java:171)
23:39:00  java.lang.RuntimeException: count = 658946
23:39:00  	at PinALot.main(PinALot.java:73)

@pshipton
Copy link
Member

pshipton commented Nov 9, 2022

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_Nightly/44
jdk_lang_0
java/lang/Thread/virtual/stress/PinALot.java#id0

@tajila
Copy link
Contributor

tajila commented Nov 9, 2022

Just posting output from my grinder here so I dont lose it.

Exception in thread "" java.lang.IllegalMonitorStateException: owner: Thread[#25,ForkJoinPool-1-worker-1,5,CarrierThreads] 
current: VirtualThread[#24]/runnable@ForkJoinPool-1-worker-1

	at java.base/java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:177)
	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1007)
	at java.base/java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:496)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.remove(ScheduledThreadPoolExecutor.java:1063)
	at java.base/java.util.concurrent.ThreadPoolExecutor.remove(ThreadPoolExecutor.java:1777)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.cancel(ScheduledThreadPoolExecutor.java:293)
	at java.base/java.lang.VirtualThread.cancel(VirtualThread.java:611)
	at java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:541)
	at java.base/java.lang.Access.parkVirtualThread(Access.java:502)
	at java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
	at java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
	at PinALot.lambda$main$0(PinALot.java:60)
	at java.base/java.lang.VirtualThread.run(VirtualThread.java:292)
	at java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
	at java.base/jdk.internal.vm.Continuation.execute(Continuation.java:171)
java.lang.RuntimeException: count = 495082
	at PinALot.main(PinALot.java:73)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:1573)

@tajila
Copy link
Contributor

tajila commented Nov 10, 2022

@dmitripivkine I've confirmed that the issue here is the carrierThread is a VirtualThread instance

@tajila
Copy link
Contributor

tajila commented Nov 15, 2022

@pshipton have you ever seen this on x86? Im thinking there is a memory ordering issue here.

@pshipton
Copy link
Member

@tajila every occurrence I've seen is recorded here, so no, not on x86. I only see alinux, plinux, and once on aix.

@tajila
Copy link
Contributor

tajila commented Nov 16, 2022

Another kind of failure

22:20:35  Exception in thread "" java.lang.RuntimeException: wrong threadobjectThread[#25,ForkJoinPool-1-worker-1,5,CarrierThreads]
22:20:35  	at java.base/java.lang.VirtualThread.scheduleUnpark(VirtualThread.java:596)
22:20:35  	at java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:534)
22:20:35  	at java.base/java.lang.Access.parkVirtualThread(Access.java:502)
22:20:35  	at java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
22:20:35  	at java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
22:20:35  	at PinALot.lambda$main$0(PinALot.java:60)
22:20:35  	at java.base/java.lang.VirtualThread.run(VirtualThread.java:292)
22:20:35  	at java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
22:20:35  	at java.base/jdk.internal.vm.Continuation.execute(Continuation.java:171)
22:20:35  java.lang.RuntimeException: count = 412599
22:20:35  	at PinALot.main(PinALot.java:73)
22:20:35  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
22:20:35  	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
22:20:35  	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
22:20:35  	at java.base/java.lang.Thread.run(Thread.java:1573)

@tajila
Copy link
Contributor

tajila commented Nov 18, 2022

so far no failures when -Xjit:disableInliningOfNatives is specified

@tajila
Copy link
Contributor

tajila commented Nov 18, 2022

@0xdaryl looks like disabling natinve inlining fixes this issue. Is there a way to determine if the result of Thread.currentThread() is being used as a constant value?

@tajila
Copy link
Contributor

tajila commented Nov 18, 2022

Also, I find it interesting that I never reproduced this on x86

@pshipton
Copy link
Member

pshipton commented Nov 23, 2022

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_Nightly/55
jdk_lang_1
java/lang/Thread/virtual/stress/PinALot.java#id0


https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_linux_Nightly/55
jdk_lang_1
java/lang/Thread/virtual/stress/PinALot.java#id0

@pshipton
Copy link
Member

pshipton commented Nov 23, 2022

@tajila see the reproduction on x86 added to the previous comment.

@pshipton
Copy link
Member

pshipton commented Nov 27, 2022

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_Nightly/56
jdk_lang_1
java/lang/Thread/virtual/stress/PinALot.java#id0


https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/59
jdk_lang_0
java/lang/Thread/virtual/stress/PinALot.java#id0


https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_linux_Nightly/58
jdk_lang_1
java/lang/Thread/virtual/stress/PinALot.java#id0


https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_mac_Nightly/63
jdk_lang_1
java/lang/Thread/virtual/stress/PinALot.java#id0


https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_Nightly/60
jdk_lang_1
java/lang/Thread/virtual/stress/PinALot.java#id0

@0xdaryl
Copy link
Contributor

0xdaryl commented Nov 29, 2022

@tajila : just wondering how the investigation here became focused on Thread.currentThread(). I'm not saying that's not related, but I'm not seeing the connection from the analysis described above.

The JIT inlined implementation is the same as it always was: insert a load of the current thread object from the threadObject field of theJ9VMThread.

@tajila
Copy link
Contributor

tajila commented Nov 29, 2022

There are places in j.l.Thread/VirtualThread where the JCL switches from the virtualThread to the carrierThread. This is to avoid yielding twice when performing blocking operations. We are seeing that in some cases, we expect the carriedthread but currentThread returns a virtual thread.

In the failure below

22:20:35  Exception in thread "" java.lang.RuntimeException: wrong threadobjectThread[#25,ForkJoinPool-1-worker-1,5,CarrierThreads]
22:20:35  	at java.base/java.lang.VirtualThread.scheduleUnpark(VirtualThread.java:596)
22:20:35  	at java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:534)
22:20:35  	at java.base/java.lang.Access.parkVirtualThread(Access.java:502)
22:20:35  	at java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
22:20:35  	at java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
22:20:35  	at PinALot.lambda$main$0(PinALot.java:60)
22:20:35  	at java.base/java.lang.VirtualThread.run(VirtualThread.java:292)
22:20:35  	at java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
22:20:35  	at java.base/jdk.internal.vm.Continuation.execute(Continuation.java:171)

here is the code

        if (!future.isDone()) {
            Thread carrier = this.carrierThread;
            // need to switch to current platform thread to avoid nested parking
            carrier.setCurrentThread(carrier);
            try {
            	if (Thread.currentThread() instanceof VirtualThread) {
            		throw new RuntimeException("wrong threadobject" + Thread.currentThread());
            	}
                future.cancel(false);
            } finally {
                carrier.setCurrentThread(this);
            }
        }

@a7ehuo
Copy link
Contributor

a7ehuo commented Mar 15, 2023

Thanks so much for the clarification @tajila. I'll try excluding Thread.currentThread() and see how it goes. If the issue happens before ReentrantLock$Sync.tryRelease, I suspect it might be related to how methods are inlined into VirtualThread.parkNanos

@a7ehuo
Copy link
Contributor

a7ehuo commented Mar 20, 2023

I'm able to reproduce the issue by excluding Thread.currentThread (Grinder 31731)

Grinder: 31731:
-Xjit:exclude={java/lang/Thread.currentThread*}

I haven't been able to repro the issue after adding more logging (Grinder 31728) as below. Locally I've tried over 500x without reproducing it with required logging. I'm still trying to repro the issue with the required logging in order to investigate it from JIT's perspective

Grinder 31728: 
-Xnoaot -Xjit:{java/lang/VirtualThread.parkNanos*}(traceFull,traceILGen,traceCG,traceInlining,debugInliner,tracePRE,log=jitlog) -Xdump:system+java+snap+jit:events=throw,filter=java/lang/IllegalMonitorStateException#java/base/java/util/concurrent/locks/ReentrantLock*,request=exclusive+prepwalk+serial+preempt

@mstoodle
Copy link
Contributor

mstoodle commented Mar 21, 2023

Hi @a7ehuo did you also specify dontInline={java/lang/Thread.currentThread*} in those jgrinder runs? I could be wrong as it's been a while, but I'm not sure if exclude={} will prevent inlining of those methods. It may not matter (hard to imagine the aliasing isn't set up properly to ensure setCurrentThread blocks reuse of the current thread) but I'd rather say something stupid than not point out something that might matter.

@a7ehuo
Copy link
Contributor

a7ehuo commented Mar 21, 2023

did you also specify dontInline={java/lang/Thread.currentThread*} in those jgrinder runs?

Thanks for pointing it out! I didn't add dontInline={java/lang/Thread.currentThread*}. I'll add that along exclude={..} and see how it goes

@mstoodle
Copy link
Contributor

mstoodle commented Mar 21, 2023

along those same lines, you may want to use a filter that excludes setCurrentThread() as well as currentThread() and validate that dontInline actually does prevent inlining for those relatively simple functions :) . Though I suppose we'd be a lot less likely to move a store around than a load. So maybe the first part isn't useful but I would make sure dontInline covers what might be recognized methods (probably does, but if you're going to the trouble to re-test....).

@mstoodle
Copy link
Contributor

@a7ehuo Any luck reproducing the problem with the updated options?

@a7ehuo
Copy link
Contributor

a7ehuo commented Mar 22, 2023

Although we can't reproduce the issue with a log file on VirtualThread.parkNanos(J)V, we found a partial JIT log file (quit early because of shutdown) in a passed run that has over 200 inlined methods, which is similar to the scenario in a failed run. The log shows after partialRedundancyElimination, Thread.currentThread is stored to a temp #2515 and later on is written to AbstractOwnableSynchronizer.exclusiveOwnerThread [1]. It was a virtual thread when it was stored to #2515. It would be an issue if it was changed to a carrier thread in between. This finding in the log confirms the scenario that @tajila suspected that Thread.currentThread was cached. @fengxue-IS in the comment and @0xdaryl pointed out currentThread sym ref set as immutableField. As the log shows, it could be an issue.

Two grinders are currently running. At the moment no failure is observed.

  1. Disable recognizing Thread.currentThread (Grinder 31825): Iteration 30x
  2. Remove setImmutableField on currentThread sym ref (Grinder 31840): Iteration 30x

Meanwhile, I'm also running tests to verify a proper fix.

[1]

n8505n    BBStart <block_609> (freq 178)                                                      [    0x775746bb5230] bci=[-1,6,523] rc=0 vc=1528 vn=- li=-1 udi=- nc=0
n20491n   astore  <temp slot 101>[#2515  Auto] [flags 0x7 0x0 ]                               [    0x77574481f4b0] bci=[-1,6,523] rc=0 vc=1528 vn=- li=-1 udi=1 nc=1
n34n        aload  CurrentThread[#318  MethodMeta +168] [flags 0x207 0x400 ]                  [    0x775746004430] bci=[-1,6,523] rc=2 vc=1528 vn=- li=- udi=- nc=0
n43n      ifacmpne --> block_3 BBStart at n41n ()                                             [    0x775746004700] bci=[-1,10,523] rc=0 vc=1528 vn=- li=-1 udi=- nc=2 flg=0x20
n34n        ==>aload
n40n        aload  this<'this' parm Ljava/lang/VirtualThread;>[#396  Parm] [flags 0x40000107 0x0 ] (X!=0 )  [    0x775746004610] bci=[-1,9,523] rc=1 vc=1528 vn=- li=- udi=694 nc=0 flg=0x4
n30n      BBEnd </block_609> ===== 
...
...
....
n14436n   BBStart <block_1184> (freq 108)                                                     [    0x775745ec9010] bci=[181,19,234] rc=0 vc=1528 vn=- li=-1 udi=- nc=0
n14432n   awrtbari  java/util/concurrent/locks/AbstractOwnableSynchronizer.exclusiveOwnerThread Ljava/lang/Thread;[#1910  Shadow +24] [flags 0x80607 0x0 ] (X!=0 )  [    0x775745ec8ed0] bci=[184,2,74] rc=0 vc=1528 vn=- li=-1 udi=- nc=3 flg=0x24
n14430n     aload  <temp slot 3>[#2277  Auto] [flags 0x20000007 0x0 ] (X!=0 X>=0 )            [    0x775745ec8e30] bci=[184,0,74] rc=2 vc=1528 vn=- li=- udi=824 nc=0 flg=0x104
n14431n     aload  <temp slot 101>[#2515  Auto] [flags 0x7 0x0 ] (X!=0 )                      [    0x775745ec8e80] bci=[184,1,74] rc=1 vc=1528 vn=- li=- udi=825 nc=0 flg=0x4
n14430n     ==>aload
n17386n   BBEnd </block_1184> =====   

@a7ehuo
Copy link
Contributor

a7ehuo commented Mar 23, 2023

Grinder run results:

  1. Disable recognizing Thread.currentThread (Grinder 31825): Iteration 30x
    29 tests, 29 ok, 0 not ok: One run exit unexpectedly. It does not look related to PinALot.java test
java/lang/invoke/defineHiddenClass/BasicTest.java false BasicTest
TEST RESULT: Failed. Unexpected exit from test [exit code: 143]
  1. Remove setImmutableField on currentThread sym ref (Grinder 31840): Iteration 30x
    29 tests, 28 ok, 1 not ok: One run exit unexpectedly. One run with failed tests. They don't look related to PinALot.java test
(1)
Test finished: java/lang/invoke/VarHandles/VarHandleTestMethodTypeDouble.java: Failed. Unexpected exit from test [exit code: 143]
...
Test finished: java/lang/invoke/VarHandles/VarHandleTestMethodTypeFloat.java: Error. Agent communication error: java.io.EOFException; check console log for any additional details
(2)
Failed test cases: 
TEST: java/lang/annotation/Missing/MissingArrayElement/MissingEnumArrayElementTest.java
TEST: java/lang/CompressExpandTest.java
TEST: java/lang/System/LoggerFinder/modules/JDKLoggerForJDKTest.java
TEST: java/lang/System/LoggerFinder/modules/LoggerInImageTest.java
TEST: java/lang/System/LoggerFinder/modules/NamedLoggerForImageTest.java
TEST: java/lang/System/LoggerFinder/modules/NamedLoggerForJDKTest.java
Test results: passed: 855; failed: 4; error: 2

java/lang/annotation/Missing/MissingArrayElement/MissingEnumArrayElementTest.java: getAnnotation() throws an ArrayStoreException when the annotation class not present

@pshipton
Copy link
Member

I don't find any issues covering those failures. They appear to be new failures we haven't seen before, which makes it likely they are introduced by the change.

@tajila
Copy link
Contributor

tajila commented Mar 23, 2023

@JasonFengJ9 @fengxue-IS Have you seen the failures Annabelle posted above?

@JasonFengJ9
Copy link
Member Author

java/lang/annotation/Missing/MissingArrayElement/MissingEnumArrayElementTest.java: getAnnotation() throws an ArrayStoreException when the annotation class not present

This is new.

Test finished: java/lang/invoke/VarHandles/VarHandleTestMethodTypeDouble.java: Failed. Unexpected exit from test [exit code: 143]
Test finished: java/lang/invoke/VarHandles/VarHandleTestMethodTypeFloat.java: Error. Agent communication error: java.io.EOFException; check console log for any additional details

No existing issue, the console log might have more info.

@fengxue-IS
Copy link
Contributor

Have not seen these issues previously

@0xdaryl
Copy link
Contributor

0xdaryl commented Mar 23, 2023

I don't find any issues covering those failures. They appear to be new failures we haven't seen before, which makes it likely they are introduced by the change.

For @a7ehuo's "change 2" above, this is not functionally equivalent to what she actually implemented. "Change 2" simply removed the "immutability" setting on the field which isn't completely correct. However, her PR correctly removes it and marks it "volatile" instead.

It is probably worth running a 30x grinder with the actual PR to verify it is clean.

@a7ehuo
Copy link
Contributor

a7ehuo commented Mar 23, 2023

It is probably worth running a 30x grinder with the actual PR to verify it is clean.

Sounds good! I'll start the grinder runs

@a7ehuo
Copy link
Contributor

a7ehuo commented Mar 24, 2023

An update on the grinder run results:

  1. PR change: Grinder ID 31905

    • Set up to run 30x, completed 8 tests, 8 ok, 0 not ok
    • Grinder was canceled “Cancelling nested steps due to timeout”.
  2. master branch: Grinder ID 31906

    • Set up to run 30x, completed 30 tests, 16 ok, 14 not ok due to the failure in PinALot.java
  3. master branch excluding test PinALot.java: Grinder ID 31909

    • Set up to run 30x, ongoing, 8 tests run so far, 7 ok,
    • 1 failed with “make[3]: *** [jdk_lang_1] Error 143", which looks similar to one of the failures observed in previous Grinder runs with the experiments

@a7ehuo
Copy link
Contributor

a7ehuo commented Mar 24, 2023

Another grinder on jdk_lang_1 with the PR #17009 change: Grinder ID 31915. 30x, all passed

@0xdaryl
Copy link
Contributor

0xdaryl commented Mar 24, 2023

Thanks @a7ehuo.

If I have this right, the summary is:

  • 14/30 failures without the PR change (master)
  • 0/30 failures with the PR
  • Sanity and OpenJDK tests succeeded on all platforms in the PR
  • The "error 143" failure was only seen in test runs without this PR (and hence is not a regression caused by it)
  • Grinder failures "2)" reported by Annabelle above were only seen with an incomplete variant of this PR and not seen again in subsequent Grinders with the PR or in just master.

@pshipton : I think we're ready to merge this.

@0xdaryl
Copy link
Contributor

0xdaryl commented Mar 24, 2023

Re-opening until fixed in 0.37.

@0xdaryl 0xdaryl reopened this Mar 24, 2023
a7ehuo added a commit to a7ehuo/openj9 that referenced this issue Mar 24, 2023
`Thread.currentThread` can be changed by JCL in
JDK19 and up. Set it as volatile for JDK19 and up.

Add `isJ9VMThreadCurrentThreadImmutable` in FrontEnd
to query whether or not `Thread.currentThread` is
immutable based on `JAVA_SPEC_VERSION`.

Fixes eclipse-openj9#16258

Co-authored-by: Daryl Maier <maier@ca.ibm.com>
Signed-off-by: Annabelle Huo <Annabelle.Huo@ibm.com>
@pshipton
Copy link
Member

Closing since #17021 is merged for 0.37

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
comp:jit jdk19 project:loom Used to track Project Loom related work test failure
Projects
None yet
Development

No branches or pull requests

8 participants