-
Bug
-
Resolution: Unresolved
-
P4
-
22
When testing JDK-8318986, we have seen a test failure in vmTestbase/nsk/monitoring/stress/thread/strace016/TestDescription.java:
```
#>
#> WARNING: switching log to verbose mode,
#> because error is complained
#>
ThreadMonitor> Test mode: DIRECTLY access to MBean
ThreadController> number of created threads: 30
ThreadController> depth for all threads: 100
ThreadController> invocation type: mixed
Starting threads.
ThreadController> locking threads
States of the threads are culminated.
# ERROR: Thread BLOCKED_ThreadMM001 wrong thread state: RUNNABLE
The following stacktrace is for failure analysis.
nsk.share.TestFailure: Thread BLOCKED_ThreadMM001 wrong thread state: RUNNABLE
at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:431)
at nsk.share.Log.complain(Log.java:402)
at nsk.monitoring.stress.thread.strace010.runIt(strace010.java:148)
at nsk.monitoring.stress.thread.strace010.run(strace010.java:99)
at nsk.monitoring.stress.thread.strace010.main(strace010.java:95)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:580)
at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
at java.base/java.lang.Thread.run(Thread.java:1570)
Checked 6 BLOCKED threads
# ERROR: Expected amount: 7 for BLOCKED threads actual: 6
Checked 7 WAITING threads
Checked 8 TIMED_WAITING threads
Checked 9 RUNNABLE threads
# ERROR: Expected amount: 8 for RUNNABLE threads actual: 9
```
I ran this test hundreds of times without failure. The output implies there is a thread that should be "blocked", but instead it is "runnable". I think the test itself contains the race condition. The harness code starts the threads, and waits before they roll to their appropriate states. But the code for blocked threads under inspection is inherently racy: for example it first notifies that we have reached the BLOCKED state, and only then blocks: https://github.com/openjdk/jdk/blob/25cebe8c3ed5c03b4da2da5bb2f7637c8cd40581/test/hotspot/jtreg/vmTestbase/nsk/monitoring/share/ThreadController.java#L577-L578
So IMO there is a tiny window where we can see "blocked" thread as "runnable". OTOH, there is a block that waits that threads are rolled to a proper state here:
https://github.com/openjdk/jdk/blob/25cebe8c3ed5c03b4da2da5bb2f7637c8cd40581/test/hotspot/jtreg/vmTestbase/nsk/monitoring/share/ThreadController.java#L298-L305
```
#>
#> WARNING: switching log to verbose mode,
#> because error is complained
#>
ThreadMonitor> Test mode: DIRECTLY access to MBean
ThreadController> number of created threads: 30
ThreadController> depth for all threads: 100
ThreadController> invocation type: mixed
Starting threads.
ThreadController> locking threads
States of the threads are culminated.
# ERROR: Thread BLOCKED_ThreadMM001 wrong thread state: RUNNABLE
The following stacktrace is for failure analysis.
nsk.share.TestFailure: Thread BLOCKED_ThreadMM001 wrong thread state: RUNNABLE
at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:431)
at nsk.share.Log.complain(Log.java:402)
at nsk.monitoring.stress.thread.strace010.runIt(strace010.java:148)
at nsk.monitoring.stress.thread.strace010.run(strace010.java:99)
at nsk.monitoring.stress.thread.strace010.main(strace010.java:95)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:580)
at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
at java.base/java.lang.Thread.run(Thread.java:1570)
Checked 6 BLOCKED threads
# ERROR: Expected amount: 7 for BLOCKED threads actual: 6
Checked 7 WAITING threads
Checked 8 TIMED_WAITING threads
Checked 9 RUNNABLE threads
# ERROR: Expected amount: 8 for RUNNABLE threads actual: 9
```
I ran this test hundreds of times without failure. The output implies there is a thread that should be "blocked", but instead it is "runnable". I think the test itself contains the race condition. The harness code starts the threads, and waits before they roll to their appropriate states. But the code for blocked threads under inspection is inherently racy: for example it first notifies that we have reached the BLOCKED state, and only then blocks: https://github.com/openjdk/jdk/blob/25cebe8c3ed5c03b4da2da5bb2f7637c8cd40581/test/hotspot/jtreg/vmTestbase/nsk/monitoring/share/ThreadController.java#L577-L578
So IMO there is a tiny window where we can see "blocked" thread as "runnable". OTOH, there is a block that waits that threads are rolled to a proper state here:
https://github.com/openjdk/jdk/blob/25cebe8c3ed5c03b4da2da5bb2f7637c8cd40581/test/hotspot/jtreg/vmTestbase/nsk/monitoring/share/ThreadController.java#L298-L305