RFR: 8324881: ObjectSynchronizer::inflate(Thread* current...) is invoked for non-current thread [v10]
Axel Boldt-Christmas
aboldtch at openjdk.org
Tue Feb 6 14:04:59 UTC 2024
On Mon, 5 Feb 2024 06:51:22 GMT, Axel Boldt-Christmas <aboldtch at openjdk.org> wrote:
>> The `ObjectSynchronizer` has always assumed that the `current` parameters are both the current thread as well as the thread that is doing the locking. The only time that we are entering on behalf of another thread is when doing re-locking in deoptimization. This has worked because the deoptee thread is suspended. However ResourceMarks have been using the wrong thread when logging is enabled.
>>
>> This change `ObjectSynchronizer` instruments the relevant methods with both a `JavaThread* locking_thread` as well as `[Java]Thread* current` to be able to use the correct thread for ResourceMarks.
>>
>> Having the `inflate` care about a `locking_thread` is a little unpleasant in my opinion. But it is required for LM_LIGHTWEIGHT.
>> Would probably be cleaner if the inflate for LM_LIGHTWEIGHT was it's own thing, as it does not share the whole INFLATING protocol. But seems like a future RFE to refactor this code.
>>
>> Can reproduce a crash by modifying `test/jdk/com/sun/jdi/EATests.java` and using `-XX:DiagnoseSyncOnValueBasedClasses=2` with LM_LEGACY or running `test/jdk/com/sun/jdi/EATests.java` with LM_LIGHTWEIGHT/LM_MONITOR and `-Xlog:monitorinflation=trace`.
>>
>> Could extend this test to capture this regression in the future (or creating a new test based on the same infrastructure). Will give it an attempt, so we have a regression test for this. But these tests get rather involved as the require a lot of jvmti setup.
>
> Axel Boldt-Christmas has updated the pull request with a new target base due to a merge or a rebase. The incremental webrev excludes the unrelated changes brought in by the merge/rebase. The pull request contains 22 additional commits since the last revision:
>
> - Merge remote-tracking branch 'upstream_jdk/master' into JDK-8324881
> - Update comment
> - Fix comments
> - Update test/jdk/com/sun/jdi/EATests.java
>
> Co-authored-by: Andrey Turbanov <turbanoff at gmail.com>
> - Update test/jdk/com/sun/jdi/EATests.java
>
> Co-authored-by: Andrey Turbanov <turbanoff at gmail.com>
> - Update test/jdk/com/sun/jdi/EATests.java
>
> Co-authored-by: Andrey Turbanov <turbanoff at gmail.com>
> - Update test/jdk/com/sun/jdi/EATests.java
>
> Co-authored-by: Andrey Turbanov <turbanoff at gmail.com>
> - Remove newline
> - Update src/hotspot/share/runtime/synchronizer.hpp
>
> Co-authored-by: Richard Reingruber <richard.reingruber at sap.com>
> - Improve EARelockingNestedInflated_03 for LM_LIGHTWEIGHT
> - ... and 12 more: https://git.openjdk.org/jdk/compare/b7fe007d...b3cc401c
Ran through tier1-tier7. All green.
Saw one test on an earlier run (commit be717d5e888b168039c29bc31163e3949d1cc7b1) which threw:
Test: vmTestbase/nsk/jdi/ThreadReference/ownedMonitorsAndFrames/ownedMonitorsAndFrames003/ownedMonitorsAndFrames003.java
Exception: nsk.share.TestFailure: Number of expected monitors and actual ones differs
```
Reran the `vmTestbase/nsk/jdi/` a couple of hundred times in the CI and ran the specific test a couple of thousand times locally, but was unable to reproduce the issue.
_The test output is attached below_
Looking at the stack trace the thread seem to be about be leave `java.lang.Object.wait, line: 384`. The successful stack trace should contain
java.lang.Object.wait0, line: -1
java.lang.Object.wait, line: 375
and be inside the wait0. As the current stack trace is on the way out wait then the monitor should be expected to be locked, which it is. Maybe this is a case of a `spurious wakeup`?
I fail to see how this change could have caused this behaviour. However I can not find any record of this sort of test failure since Java 9. So I am a bit cautious. Regardless it looks to be very intermittent.
My plan is to integrate this tomorrow unless anyone objects.
<details><summary>Test Output</summary>
<pre>
binder> VirtualMachineManager: version 23.0
binder> Finding connector: default
binder> LaunchingConnector:
binder> name: com.sun.jdi.CommandLineLaunch
binder> description: Launches target using Sun Java VM command line and attaches to it
binder> transport: com.sun.tools.jdi.SunCommandLineLauncher$2 at 20b19474
binder> Connector arguments:
binder> main=nsk.share.MainWrapper Virtual nsk.share.jdi.OwnedMonitorsDebuggee \u0000-verbose\u0000 \u0000-arch=linux-x64\u0000 \u0000-waittime=5\u0000 \u0000-debugee.vmkind=java\u0000 \u0000-transport.address=dynamic\u0000 \u0000-debugee.vmkeys="-XX:MaxRAMPercentage=4.16667 -Dtest.boot.jdk=<omitted> -Djava.io.tmpdir=<omitted> -Duse.JTREG_TEST_THREAD_FACTORY=Virtual -XX:+UseZGC -XX:+ZGenerational -XX:-VerifyContinuations"\u0000 \u0000-pipe.port=51475\u0000
binder> includevirtualthreads=y
binder> quote=\u0000
binder> home=<omitted>
binder> vmexec=java
binder> suspend=true
binder> options=-XX:MaxRAMPercentage=4.16667 -Dtest.boot.jdk=<omitted> -Djava.io.tmpdir=<omitted> -Duse.JTREG_TEST_THREAD_FACTORY=Virtual -XX:+UseZGC -XX:+ZGenerational -XX:-VerifyContinuations -Djdk.virtualThreadScheduler.parallelism=15
binder> Launching debugee
binder> Waiting for VM initialized
Initial VMStartEvent received: VMStartEvent in thread main
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Breakpoint set:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (disabled)
debugee.stderr> Debuggee: received the command: createLockingThread:ownedMonitorsAndFrames003_LockingThread1:SYNCHRONIZED_METHOD:SYNCHRONIZED_THREAD_METHOD:SYNCHRONIZED_STATIC_THREAD_METHOD:SYNCHRONIZED_OBJECT_BLOCK:SYNCHRONIZED_STATIC_METHOD
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Enter synchronized method
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Enter synchronized thread method
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Enter synchronized static thread method
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Enter synchronized(object) block
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Enter synchronized static method
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: relinquishMonitor:ownedMonitorsAndFrames003_LockingThread1:0
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Relinquish monitor: nsk.share.locks.ClassWithSynchronizedMethods at 553383f8
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: acquireRelinquishedMonitor:ownedMonitorsAndFrames003_LockingThread1
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Acquire relinquished monitor: nsk.share.locks.ClassWithSynchronizedMethods at 553383f8
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: relinquishMonitor:ownedMonitorsAndFrames003_LockingThread1:1
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Relinquish monitor: Thread[#63,ownedMonitorsAndFrames003_LockingThread1,5,VirtualThreads]
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
# ERROR: Number of expected monitors and actual ones differs
The following stacktrace is for failure analysis.
nsk.share.TestFailure: Number of expected monitors and actual ones differs
at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:431)
at nsk.share.Log.complain(Log.java:402)
at nsk.share.jdi.OwnedMonitorsDebugger.compare(OwnedMonitorsDebugger.java:161)
at nsk.share.jdi.OwnedMonitorsDebugger.checkMonitorInfo(OwnedMonitorsDebugger.java:266)
at nsk.jdi.ThreadReference.ownedMonitorsAndFrames.ownedMonitorsAndFrames003.ownedMonitorsAndFrames003.doTest(ownedMonitorsAndFrames003.java:130)
at nsk.share.jdi.TestDebuggerType2.runIt(TestDebuggerType2.java:214)
at nsk.jdi.ThreadReference.ownedMonitorsAndFrames.ownedMonitorsAndFrames003.ownedMonitorsAndFrames003.run(ownedMonitorsAndFrames003.java:77)
at nsk.jdi.ThreadReference.ownedMonitorsAndFrames.ownedMonitorsAndFrames003.ownedMonitorsAndFrames003.main(ownedMonitorsAndFrames003.java:73)
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.VirtualThread.run(VirtualThread.java:329)
# ERROR: Expected: 4, actual: 5
# ERROR: Unexpected monitor in result of ownedMonitorsAndFrames(): instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953) Depth: 9 Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
ACTUAL MONITORS (total 5):
Monitor: instance of java.lang.Class(reflected class=nsk.share.locks.ClassWithSynchronizedMethods, id=954)
Depth: 3
Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
Monitor: instance of java.lang.Object(id=980)
Depth: 5
Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
Monitor: instance of java.lang.Class(reflected class=nsk.share.locks.LockingThread, id=950)
Depth: 7
Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
Monitor: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
Depth: 9
Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
Monitor: instance of nsk.share.locks.ClassWithSynchronizedMethods(id=981)
Depth: 11
Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
EXPECTED MONITORS (total 4):
Monitor: instance of java.lang.Object(id=980)
Depth: 5
Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
Monitor: instance of java.lang.Class(reflected class=nsk.share.locks.LockingThread, id=950)
Depth: 7
Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
Monitor: instance of nsk.share.locks.ClassWithSynchronizedMethods(id=981)
Depth: 11
Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
Monitor: instance of java.lang.Class(reflected class=nsk.share.locks.ClassWithSynchronizedMethods, id=954)
Depth: 3
Thread: instance of nsk.share.locks.LockingThread(name='ownedMonitorsAndFrames003_LockingThread1', id=953)
Thread frames:
java.lang.Object.wait, line: 384
nsk.share.locks.LockingThread.doWait, line: 443
nsk.share.locks.LockingThread.createStackFrame, line: 285
nsk.share.locks.ClassWithSynchronizedMethods.synchronizedStaticMethod, line: 633
nsk.share.locks.LockingThread.createStackFrame, line: 271
nsk.share.locks.LockingThread.synchronizedObjectBlock, line: 591
nsk.share.locks.LockingThread.createStackFrame, line: 277
nsk.share.locks.LockingThread.synchronizedStaticMethod, line: 481
nsk.share.locks.LockingThread.createStackFrame, line: 273
nsk.share.locks.LockingThread.synchronizedMethod, line: 504
nsk.share.locks.LockingThread.createStackFrame, line: 269
nsk.share.locks.ClassWithSynchronizedMethods.synchronizedMethod, line: 619
nsk.share.locks.LockingThread.createStackFrame, line: 267
nsk.share.locks.LockingThread.run, line: 467
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: acquireRelinquishedMonitor:ownedMonitorsAndFrames003_LockingThread1
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Acquire relinquished monitor: Thread[#63,ownedMonitorsAndFrames003_LockingThread1,5,VirtualThreads]
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: relinquishMonitor:ownedMonitorsAndFrames003_LockingThread1:2
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Relinquish monitor: class nsk.share.locks.LockingThread
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: acquireRelinquishedMonitor:ownedMonitorsAndFrames003_LockingThread1
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Acquire relinquished monitor: class nsk.share.locks.LockingThread
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: relinquishMonitor:ownedMonitorsAndFrames003_LockingThread1:3
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Relinquish monitor: java.lang.Object at 2441ad00
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: acquireRelinquishedMonitor:ownedMonitorsAndFrames003_LockingThread1
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Acquire relinquished monitor: java.lang.Object at 2441ad00
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: relinquishMonitor:ownedMonitorsAndFrames003_LockingThread1:4
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Relinquish monitor: class nsk.share.locks.ClassWithSynchronizedMethods
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: acquireRelinquishedMonitor:ownedMonitorsAndFrames003_LockingThread1
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Acquire relinquished monitor: class nsk.share.locks.ClassWithSynchronizedMethods
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: stopLockingThread:ownedMonitorsAndFrames003_LockingThread1
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Exit synchronized static method
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Exit synchronized(object) block
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Exit synchronized static thread method
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Exit synchronized thread method
debugee.stderr> ownedMonitorsAndFrames003_LockingThread1: Exit synchronized method
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
binder> Waiting for event by request:
breakpoint request nsk.share.jpda.AbstractDebuggeeTest:63 (enabled)
debugee.stderr> Debuggee: received the command: forceBreakpoint
binder> Got requested event:
BreakpointEvent at nsk.share.jpda.AbstractDebuggeeTest:63 in thread OwnedMonitorDebuggeeMainThread
debugee.stderr> In breakpoint method: 'AbstractDebuggeeTest.breakpointMethod()'
debugee.stderr> Debuggee nsk.share.jdi.OwnedMonitorsDebuggee : sending the command: ready
debugee.stderr> Debuggee: received the command: quit
debugee.stderr> Debuggee: exiting
Debuggee's process finished with status: 95
TEST FAILED
</pre>
</details>
-------------
PR Comment: https://git.openjdk.org/jdk/pull/17626#issuecomment-1929735364
More information about the hotspot-dev
mailing list