RFR JDK-8170089: nsk/jdi/EventSet/resume/resume008: ERROR: suspendCounts don't match for : Common-Cleaner
Chris Plummer
chris.plummer at oracle.com
Fri Jul 20 18:37:22 UTC 2018
Hi Gary,
The test fails if the breakpoint event comes in after the test captures
the initial thread suspend counts and before the test captures the 2nd
suspend counts.
debugger> getting : Map<String, Integer> suspendsCounts1
debugger> {Reference Handler=1, Common-Cleaner=1, main=1, Signal
Dispatcher=1, Finalizer=1}
debugger> eventSet.resume;
debugger> getting : Map<String, Integer> suspendsCounts2
EventHandler> Received event set with policy = SUSPEND_ALL
EventHandler> Event: BreakpointEventImpl req breakpoint request
nsk.jdi.EventSet.resume.resume008a:60 (enabled)
debugger> Received communication breakpoint event.
debugger> {Reference Handler=2, Common-Cleaner=2, main=1, Signal
Dispatcher=2, Finalizer=2}
So we end up with some threads starting with 1 suspend and ending with 2
(not clear to me why main is still at 1).
It will pass if the breakpoint comes in after it does both of suspend
count checks, as you have shown with the sleep(100) solution. Output
looks like this:
debugger> got new ThreadStartEvent with propety 'number' ==
ThreadStartRequest1
...
debugger> ......--> vm.suspend();
debugger> getting : Map<String, Integer> suspendsCounts1
debugger> {Reference Handler=1, thread0=1, Common-Cleaner=1, main=1,
Signal Dispatcher=1, Finalizer=1}
debugger> eventSet.resume;
debugger> getting : Map<String, Integer> suspendsCounts2
debugger> {Reference Handler=1, thread0=1, Common-Cleaner=1, main=1,
Signal Dispatcher=1, Finalizer=1}
...
debugger> Received communication breakpoint event.
I've also shown that it passes if the breakpoint always comes in before
capturing the initial suspend counts. I added a sleep on the debugger
side right after eventHandler.waitForRequestedEventSet() returns. Output
looks like:
debugger> Received communication breakpoint event.
debugger> got new ThreadStartEvent with propety 'number' ==
ThreadStartRequest1
...
debugger> ......--> vm.suspend();
debugger> getting : Map<String, Integer> suspendsCounts1
debugger> {Reference Handler=2, thread0=2, Common-Cleaner=2, main=2,
Signal Dispatcher=2, Finalizer=2}
debugger> eventSet.resume;
debugger> getting : Map<String, Integer> suspendsCounts2
debugger> {Reference Handler=2, thread0=2, Common-Cleaner=2, main=2,
Signal Dispatcher=2, Finalizer=2}
I think we should add synchronization to force one of these two
outcomes. For the first, you would need to make the debugger modify some
variable that the debuggee is watching (sitting in a loop waiting for it
to change). For the second, you can rely on the existing
methodForCommunication() approach. You just need to restructure the
debugger a bit. I had started down this path late Wednesday, but got
sidetracked by a few other things. I can look into it some more if you'd
like.
thanks,
Chris
On 7/19/18 5:08 AM, Gary Adams wrote:
> In the successful run below "the first acquire thread suspend counts,
> resume,
> and the second acquire thread suspend counts" is not interrupted by the
> breakpoint event.
>
> Note that the failed thread0 case the test thread finishes rapidly.
> [2018-01-22T20:33:46.86] debugee.stderr> **> debuggee: 'run': enter ::
> threadName == thread0 *[2018-01-22T20:33:46.86] debugee.stderr> **>
> debuggee: 'run': exit :: threadName == thread0*
>
> and the successful test run , the thread0 run method exits after the
> thread1
> has started.
>
> debugger> :::::: case: # 1
> debugger> ......waiting for new ThreadStartEvent : 1
> EventHandler> waitForRequestedEventSet: enabling remove of listener
> nsk.share.jdi.EventHandler$7 at 616bc3ae
> EventHandler> Adding listener nsk.share.jdi.EventHandler$7 at 616bc3ae
> EventHandler> waitForRequestedEventSet: vm.resume called
> EventHandler> Received event set with policy = SUSPEND_EVENT_THREAD
> *debugee.stderr> **> debuggee: 'run': exit :: threadName == thread0*
>
>
> Here's a recent mach5 failed log:
> [2018-01-22T20:33:45.65] # [2018-01-22T20:33:45.65] export
> TEST_CLEANUP [2018-01-22T20:33:45.65] export SHELL
> [2018-01-22T20:33:45.65] export DISPLAY [2018-01-22T20:33:45.65]
> export LIBJSIG_PATH [2018-01-22T20:33:45.65] export TESTBASE
> [2018-01-22T20:33:45.65] export JAVA_OPTS [2018-01-22T20:33:45.65]
> export RAS_OPTIONS [2018-01-22T20:33:45.65] export HOME
> [2018-01-22T20:33:45.65] export LD_LIBRARY_PATH
> [2018-01-22T20:33:45.65] export CLASSPATH [2018-01-22T20:33:45.65]
> export TEMP [2018-01-22T20:33:45.65] export TESTED_JAVA_HOME
> [2018-01-22T20:33:45.65] export BASH_ENV [2018-01-22T20:33:45.65]
> export PATH [2018-01-22T20:33:45.65] TEST_DEST_DIR="resume008"
> [2018-01-22T20:33:45.65] # Actual: TEST_DEST_DIR=resume008
> [2018-01-22T20:33:45.65] TESTNAME="${test_case_name}"
> [2018-01-22T20:33:45.65] # Actual: TESTNAME=resume008
> [2018-01-22T20:33:45.65] testName="nsk/jdi/EventSet/resume//resume008"
> [2018-01-22T20:33:45.65] # Actual:
> testName=nsk/jdi/EventSet/resume//resume008 [2018-01-22T20:33:45.65]
> TESTDIR="${test_work_dir}" [2018-01-22T20:33:45.65] # Actual:
> TESTDIR=/scratch/opt/mach5/mesos/work_dir/slaves/450fa0f5-8733-43f8-b866-79fe3e86d200-S1/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/73521160-5cd7-4903-8c37-ced4a457889d/runs/43aad3bc-5f94-43a8-85b4-40524a4342b6/testoutput/tonga/mach5-one.Linux.amd64/resume008
> [2018-01-22T20:33:45.65] testWorkDir="${test_work_dir}/"
> [2018-01-22T20:33:45.65] # Actual:
> testWorkDir=/scratch/opt/mach5/mesos/work_dir/slaves/450fa0f5-8733-43f8-b866-79fe3e86d200-S1/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/73521160-5cd7-4903-8c37-ced4a457889d/runs/43aad3bc-5f94-43a8-85b4-40524a4342b6/testoutput/tonga/mach5-one.Linux.amd64/resume008/
> [2018-01-22T20:33:45.65] export testWorkDir [2018-01-22T20:33:45.65]
> tlogOutFile="${test_work_dir}/${test_name}.tlog"
> [2018-01-22T20:33:45.65] # Actual:
> tlogOutFile=/scratch/opt/mach5/mesos/work_dir/slaves/450fa0f5-8733-43f8-b866-79fe3e86d200-S1/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/73521160-5cd7-4903-8c37-ced4a457889d/runs/43aad3bc-5f94-43a8-85b4-40524a4342b6/testoutput/tonga/mach5-one.Linux.amd64/resume008/resume008.tlog
> [2018-01-22T20:33:45.65]
> testErrFile="${test_work_dir}/${test_name}.err"
> [2018-01-22T20:33:45.65] # Actual:
> testErrFile=/scratch/opt/mach5/mesos/work_dir/slaves/450fa0f5-8733-43f8-b866-79fe3e86d200-S1/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/73521160-5cd7-4903-8c37-ced4a457889d/runs/43aad3bc-5f94-43a8-85b4-40524a4342b6/testoutput/tonga/mach5-one.Linux.amd64/resume008/resume008.err
> [2018-01-22T20:33:45.65] EXECUTE_CLASS="${test_name}"
> [2018-01-22T20:33:45.66] # Actual: EXECUTE_CLASS=resume008
> [2018-01-22T20:33:45.66]
> NSK_STRESS_METASPACE_OPTS="-XX:MaxMetaspaceSize=128m
> -XX:CompressedClassSpaceSize=64m -XX:MaxHeapSize=512m
> -Xlog:gc(ASTERISK_SUBST),gc+heap=trace" [2018-01-22T20:33:45.66] #
> Actual: NSK_STRESS_METASPACE_OPTS=-XX:MaxMetaspaceSize=128m
> -XX:CompressedClassSpaceSize=64m -XX:MaxHeapSize=512m
> -Xlog:gc*,gc+heap=trace [2018-01-22T20:33:45.66] export
> NSK_STRESS_METASPACE_OPTS [2018-01-22T20:33:45.66]
> EXECUTE_CLASS="nsk.jdi.EventSet.resume.resume008"
> [2018-01-22T20:33:45.66] # Actual:
> EXECUTE_CLASS=nsk.jdi.EventSet.resume.resume008
> [2018-01-22T20:33:45.66] TEST_ARGS="${JDI_TEST_KEYS}
> -debugee.vmkeys=${JDI_DEBUGEE_VM_KEYS}" [2018-01-22T20:33:45.66] #
> Actual: TEST_ARGS=-verbose -arch=linux-amd64 -waittime=5
> -debugee.vmkind=java -transport.address=dynamic
> -debugee.vmkeys=-XX:MaxRAMPercentage=12.5 [2018-01-22T20:33:45.66]
> JAVA="${TESTED_JAVA_HOME}/bin/${DEBUGGER_KIND_OF_JAVA}"
> [2018-01-22T20:33:45.66] # Actual:
> JAVA=/scratch/opt/mach5/mesos/work_dir/jib-master/install/2018-01-22-1955354.leonid.mesnik.hs/linux-x64.jdk/jdk-10/bin/java
> [2018-01-22T20:33:45.66] JAVA_OPTS="${DEBUGGER_JAVA_OPTS}"
> [2018-01-22T20:33:45.66] # Actual: JAVA_OPTS= [2018-01-22T20:33:45.66]
> APPLICATION_TIMEOUT="${TIMEOUT}" [2018-01-22T20:33:45.66] # Actual:
> APPLICATION_TIMEOUT=30 [2018-01-22T20:33:45.66]
> CLASSPATH="${test_work_dir}${PS}${CLASSPATH}" [2018-01-22T20:33:45.66]
> # Actual:
> CLASSPATH=/scratch/opt/mach5/mesos/work_dir/slaves/450fa0f5-8733-43f8-b866-79fe3e86d200-S1/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/73521160-5cd7-4903-8c37-ced4a457889d/runs/43aad3bc-5f94-43a8-85b4-40524a4342b6/testoutput/tonga/mach5-one.Linux.amd64/resume008:/scratch/opt/mach5/mesos/work_dir/jib-master/install/2018-01-22-1955354.leonid.mesnik.hs/linux-x64.test/hotspot/closed/tonga/bin/classes:
> [2018-01-22T20:33:45.66] export CLASSPATH [2018-01-22T20:33:45.66]
> ${JAVA} ${JAVA_OPTS} ${EXECUTE_CLASS} ${TEST_ARGS}
> [2018-01-22T20:33:45.66] # Actual:
> /scratch/opt/mach5/mesos/work_dir/jib-master/install/2018-01-22-1955354.leonid.mesnik.hs/linux-x64.jdk/jdk-10/bin/java
> nsk.jdi.EventSet.resume.resume008 -verbose -arch=linux-amd64
> -waittime=5 -debugee.vmkind=java -transport.address=dynamic
> -debugee.vmkeys=-XX:MaxRAMPercentage=12.5 [2018-01-22T20:33:46.01]
> binder> VirtualMachineManager: version 9.0 [2018-01-22T20:33:46.05]
> binder> Finding connector: default [2018-01-22T20:33:46.05] binder>
> LaunchingConnector: [2018-01-22T20:33:46.06] binder> name:
> com.sun.jdi.CommandLineLaunch [2018-01-22T20:33:46.06] binder>
> description: Launches target using Sun Java VM command line and
> attaches to it [2018-01-22T20:33:46.06] binder> transport:
> com.sun.tools.jdi.SunCommandLineLauncher$2 at 457e2f02
> [2018-01-22T20:33:46.19] binder> Connector arguments:
> [2018-01-22T20:33:46.19] binder>
> home=/scratch/opt/mach5/mesos/work_dir/jib-master/install/2018-01-22-1955354.leonid.mesnik.hs/linux-x64.jdk/jdk-10
> [2018-01-22T20:33:46.19] binder> vmexec=java [2018-01-22T20:33:46.19]
> binder> options=-XX:MaxRAMPercentage=12.5 [2018-01-22T20:33:46.20]
> binder> main=nsk.jdi.EventSet.resume.resume008a "-verbose"
> "-arch=linux-amd64" "-waittime=5" "-debugee.vmkind=java"
> "-transport.address=dynamic"
> "-debugee.vmkeys=-XX:MaxRAMPercentage=12.5" "-pipe.port=28038"
> [2018-01-22T20:33:46.20] binder> quote=" [2018-01-22T20:33:46.20]
> binder> suspend=true [2018-01-22T20:33:46.20] binder> Launching
> debugee [2018-01-22T20:33:46.56] binder> Waiting for VM initialized
> [2018-01-22T20:33:46.60] Initial VMStartEvent received: VMStartEvent
> in thread main [2018-01-22T20:33:46.61] EventHandler> Adding listener
> nsk.share.jdi.EventHandler$1 at 1e7c7811 [2018-01-22T20:33:46.61]
> EventHandler> Adding listener nsk.share.jdi.EventHandler$2 at 1a3869f4
> [2018-01-22T20:33:46.61] EventHandler> Adding listener
> nsk.share.jdi.EventHandler$3 at 77f99a05 [2018-01-22T20:33:46.61]
> EventHandler> Adding listener nsk.share.jdi.EventHandler$4 at 3aeaafa6
> [2018-01-22T20:33:46.61] EventHandler> Adding listener
> nsk.share.jdi.EventHandler$5 at 4d3167f4 [2018-01-22T20:33:46.62]
> EventHandler> waitForRequestedEvent: enabling remove of listener
> nsk.share.jdi.EventHandler$6 at 4eb7f003 [2018-01-22T20:33:46.62]
> EventHandler> Adding listener nsk.share.jdi.EventHandler$6 at 4eb7f003
> [2018-01-22T20:33:46.62] EventHandler> waitForRequestedEvent:
> vm.resume called [2018-01-22T20:33:46.67] EventHandler> Received event
> set with policy = SUSPEND_EVENT_THREAD [2018-01-22T20:33:46.68]
> EventHandler> Event: ClassPrepareEventImpl req class prepare request
> (enabled) [2018-01-22T20:33:46.69] EventHandler>
> waitForRequestedEvent: Received event(ClassPrepareEvent in thread
> main) for request(class prepare request (enabled))
> [2018-01-22T20:33:46.69] EventHandler> Removing listener
> nsk.share.jdi.EventHandler$6 at 4eb7f003 [2018-01-22T20:33:46.69]
> debugger> Received ClassPrepareEvent for debuggee class:
> nsk.jdi.EventSet.resume.resume008a [2018-01-22T20:33:46.71] binder>
> Breakpoint set: [2018-01-22T20:33:46.71] breakpoint request
> nsk.jdi.EventSet.resume.resume008a:60 (disabled)
> [2018-01-22T20:33:46.71] EventHandler> Adding listener
> nsk.share.jdi.TestDebuggerType1$1 at 43738a82 [2018-01-22T20:33:46.71]
> debugger> TESTING BEGINS [2018-01-22T20:33:46.71] debugger> RESUME
> DEBUGGEE VM [2018-01-22T20:33:46.72] debugger>
> shouldRunAfterBreakpoint: entered [2018-01-22T20:33:46.72] debugger>
> shouldRunAfterBreakpoint: waiting for breakpoint event during 1 sec.
> [2018-01-22T20:33:46.84] EventHandler> Received event set with policy
> = SUSPEND_ALL [2018-01-22T20:33:46.84] EventHandler> Event:
> BreakpointEventImpl req breakpoint request
> nsk.jdi.EventSet.resume.resume008a:60 (enabled)
> [2018-01-22T20:33:46.84] debugger> Received communication breakpoint
> event. [2018-01-22T20:33:46.84] debugger> shouldRunAfterBreakpoint:
> received breakpoint event. [2018-01-22T20:33:46.84] debugee.stderr>
> **> debuggee: debuggee started! [2018-01-22T20:33:46.85] debugger>
> shouldRunAfterBreakpoint: exited with true. [2018-01-22T20:33:46.85]
> debugger> :::::: case: # 0 [2018-01-22T20:33:46.85] debugger>
> ......waiting for new ThreadStartEvent : 0 [2018-01-22T20:33:46.85]
> EventHandler> waitForRequestedEventSet: enabling remove of listener
> nsk.share.jdi.EventHandler$7 at 6ec8211c [2018-01-22T20:33:46.85]
> EventHandler> Adding listener nsk.share.jdi.EventHandler$7 at 6ec8211c
> [2018-01-22T20:33:46.85] EventHandler> waitForRequestedEventSet:
> vm.resume called [2018-01-22T20:33:46.86] debugee.stderr> **>
> debuggee: 'run': enter :: threadName == thread0
> [2018-01-22T20:33:46.86] debugee.stderr> **> debuggee: 'run': exit ::
> threadName == thread0 [2018-01-22T20:33:46.86] EventHandler> Received
> event set with policy = SUSPEND_NONE [2018-01-22T20:33:46.86]
> EventHandler> waitForRequestedEventSet: Received event set for
> request: thread start request (enabled) [2018-01-22T20:33:46.86]
> EventHandler> Event: ThreadStartEventImpl req thread start request
> (enabled) [2018-01-22T20:33:46.86] EventHandler> Removing listener
> nsk.share.jdi.EventHandler$7 at 6ec8211c [2018-01-22T20:33:46.86]
> debugger> got new ThreadStartEvent with propety 'number' ==
> ThreadStartRequest1 [2018-01-22T20:33:46.86] debugger> ......checking
> up on EventSet.resume() [2018-01-22T20:33:46.86] debugger> ......-->
> vm.suspend(); [2018-01-22T20:33:46.87] debugger> getting : Map<String,
> Integer> suspendsCounts1 [2018-01-22T20:33:46.87] debugger> {Reference
> Handler=1, Common-Cleaner=1, main=1, Signal Dispatcher=1, Finalizer=1}
> [2018-01-22T20:33:46.87] debugger> eventSet.resume;
> [2018-01-22T20:33:46.87] debugger> getting : Map<String, Integer>
> suspendsCounts2 [2018-01-22T20:33:46.87] EventHandler> Received event
> set with policy = SUSPEND_ALL [2018-01-22T20:33:46.87] EventHandler>
> Event: BreakpointEventImpl req breakpoint request
> nsk.jdi.EventSet.resume.resume008a:60 (enabled)
> [2018-01-22T20:33:46.87] debugger> Received communication breakpoint
> event. [2018-01-22T20:33:46.87] debugger> {Reference Handler=2,
> Common-Cleaner=2, main=1, Signal Dispatcher=2, Finalizer=2}
> [2018-01-22T20:33:46.87] debugger> getting : int policy =
> eventSet.suspendPolicy(); [2018-01-22T20:33:46.87] debugger> case
> SUSPEND_NONE [2018-01-22T20:33:46.87] debugger> checking Reference
> Handler [2018-01-22T20:33:46.87] # ERROR: debugger> ERROR:
> suspendCounts don't match for : Reference Handler
> [2018-01-22T20:33:46.88] The following stacktrace is for Aurora. Used
> to create a RULE: [2018-01-22T20:33:46.88] nsk.share.TestFailure:
> debugger> ERROR: suspendCounts don't match for : Reference Handler
> [2018-01-22T20:33:46.88] at
> nsk.share.Log.logExceptionForAurora(Log.java:411)
> [2018-01-22T20:33:46.88] at nsk.share.Log.complain(Log.java:380)
> [2018-01-22T20:33:46.88] at
> nsk.share.jdi.TestDebuggerType1.complain(TestDebuggerType1.java:63)
> [2018-01-22T20:33:46.88] at
> nsk.jdi.EventSet.resume.resume008.testRun(resume008.java:163)
> [2018-01-22T20:33:46.88] at
> nsk.share.jdi.TestDebuggerType1.runThis(TestDebuggerType1.java:104)
> [2018-01-22T20:33:46.88] at
> nsk.jdi.EventSet.resume.resume008.run(resume008.java:62)
> [2018-01-22T20:33:46.88] at
> nsk.jdi.EventSet.resume.resume008.main(resume008.java:57)
> [2018-01-22T20:33:46.88] # ERROR: debugger> before resuming : 1
> [2018-01-22T20:33:46.88] # ERROR: debugger> after resuming : 2
> [2018-01-22T20:33:46.88] debugger> ......--> vm.resume()
> [2018-01-22T20:33:46.88] debugger> shouldRunAfterBreakpoint: entered
> [2018-01-22T20:33:46.88] debugger> shouldRunAfterBreakpoint: received
> breakpoint event. [2018-01-22T20:33:46.88] debugger>
> shouldRunAfterBreakpoint: exited with true. [2018-01-22T20:33:46.88]
> debugger> :::::: case: # 1 [2018-01-22T20:33:46.88] debugger>
> ......waiting for new ThreadStartEvent : 1 [2018-01-22T20:33:46.88]
> EventHandler> waitForRequestedEventSet: enabling remove of listener
> nsk.share.jdi.EventHandler$7 at 548ad73b [2018-01-22T20:33:46.88]
> EventHandler> Adding listener nsk.share.jdi.EventHandler$7 at 548ad73b
> [2018-01-22T20:33:46.88] EventHandler> waitForRequestedEventSet:
> vm.resume called [2018-01-22T20:33:46.88] EventHandler> Received event
> set with policy = SUSPEND_EVENT_THREAD [2018-01-22T20:33:46.88]
> EventHandler> waitForRequestedEventSet: Received event set for
> request: thread start request (enabled) [2018-01-22T20:33:46.88]
> EventHandler> Event: ThreadStartEventImpl req thread start request
> (enabled) [2018-01-22T20:33:46.88] EventHandler> Removing listener
> nsk.share.jdi.EventHandler$7 at 548ad73b [2018-01-22T20:33:46.88]
> debugger> got new ThreadStartEvent with propety 'number' ==
> ThreadStartRequest2 [2018-01-22T20:33:46.88] debugger> ......checking
> up on EventSet.resume() [2018-01-22T20:33:46.88] debugger> ......-->
> vm.suspend(); [2018-01-22T20:33:46.88] debugger> getting : Map<String,
> Integer> suspendsCounts1 [2018-01-22T20:33:46.89] debugger> {Reference
> Handler=1, thread1=2, Common-Cleaner=1, main=1, Signal Dispatcher=1,
> Finalizer=1} [2018-01-22T20:33:46.89] debugger> eventSet.resume;
> [2018-01-22T20:33:46.89] debugger> getting : Map<String, Integer>
> suspendsCounts2 [2018-01-22T20:33:46.89] debugger> {Reference
> Handler=1, thread1=1, Common-Cleaner=1, main=1, Signal Dispatcher=1,
> Finalizer=1} [2018-01-22T20:33:46.89] debugger> getting : int policy =
> eventSet.suspendPolicy(); [2018-01-22T20:33:46.89] debugger> case
> SUSPEND_THREAD [2018-01-22T20:33:46.89] debugger> checking Reference
> Handler [2018-01-22T20:33:46.89] debugger> checking thread1
> [2018-01-22T20:33:46.89] debugger> checking Common-Cleaner
> [2018-01-22T20:33:46.89] debugger> checking main
> [2018-01-22T20:33:46.90] debugger> checking Signal Dispatcher
> [2018-01-22T20:33:46.90] debugger> checking Finalizer
> [2018-01-22T20:33:46.90] debugger> ......--> vm.resume()
> [2018-01-22T20:33:46.90] debugger> shouldRunAfterBreakpoint: entered
> [2018-01-22T20:33:46.90] debugger> shouldRunAfterBreakpoint: waiting
> for breakpoint event during 1 sec. [2018-01-22T20:33:46.90]
> debugee.stderr> **> debuggee: 'run': enter :: threadName == thread1
> [2018-01-22T20:33:46.90] debugee.stderr> **> debuggee: 'run': exit ::
> threadName == thread1 [2018-01-22T20:33:46.90] EventHandler> Received
> event set with policy = SUSPEND_ALL [2018-01-22T20:33:46.90]
> EventHandler> Event: BreakpointEventImpl req breakpoint request
> nsk.jdi.EventSet.resume.resume008a:60 (enabled)
> [2018-01-22T20:33:46.90] debugger> Received communication breakpoint
> event. [2018-01-22T20:33:46.90] debugger> shouldRunAfterBreakpoint:
> received breakpoint event. [2018-01-22T20:33:46.90] debugger>
> shouldRunAfterBreakpoint: exited with true. [2018-01-22T20:33:46.90]
> debugger> :::::: case: # 2 [2018-01-22T20:33:46.90] debugger>
> ......waiting for new ThreadStartEvent : 2 [2018-01-22T20:33:46.90]
> EventHandler> waitForRequestedEventSet: enabling remove of listener
> nsk.share.jdi.EventHandler$7 at 2641e737 [2018-01-22T20:33:46.90]
> EventHandler> Adding listener nsk.share.jdi.EventHandler$7 at 2641e737
> [2018-01-22T20:33:46.90] EventHandler> waitForRequestedEventSet:
> vm.resume called [2018-01-22T20:33:46.90] EventHandler> Received event
> set with policy = SUSPEND_ALL [2018-01-22T20:33:46.90] EventHandler>
> waitForRequestedEventSet: Received event set for request: thread start
> request (enabled) [2018-01-22T20:33:46.90] EventHandler> Event:
> ThreadStartEventImpl req thread start request (enabled)
> [2018-01-22T20:33:46.90] EventHandler> Removing listener
> nsk.share.jdi.EventHandler$7 at 2641e737 [2018-01-22T20:33:46.90]
> debugger> got new ThreadStartEvent with propety 'number' ==
> ThreadStartRequest3 [2018-01-22T20:33:46.90] debugger> ......checking
> up on EventSet.resume() [2018-01-22T20:33:46.90] debugger> ......-->
> vm.suspend(); [2018-01-22T20:33:46.90] debugger> getting : Map<String,
> Integer> suspendsCounts1 [2018-01-22T20:33:46.91] debugger> {Reference
> Handler=2, thread2=2, Common-Cleaner=2, main=2, Signal Dispatcher=2,
> Finalizer=2} [2018-01-22T20:33:46.91] debugger> eventSet.resume;
> [2018-01-22T20:33:46.91] debugger> getting : Map<String, Integer>
> suspendsCounts2 [2018-01-22T20:33:46.91] debugger> {Reference
> Handler=1, thread2=1, Common-Cleaner=1, main=1, Signal Dispatcher=1,
> Finalizer=1} [2018-01-22T20:33:46.91] debugger> getting : int policy =
> eventSet.suspendPolicy(); [2018-01-22T20:33:46.91] debugger> case
> SUSPEND_ALL [2018-01-22T20:33:46.91] debugger> checking Reference
> Handler [2018-01-22T20:33:46.91] debugger> checking thread2
> [2018-01-22T20:33:46.91] debugger> checking Common-Cleaner
> [2018-01-22T20:33:46.91] debugger> checking main
> [2018-01-22T20:33:46.91] debugger> checking Signal Dispatcher
> [2018-01-22T20:33:46.91] debugger> checking Finalizer
> [2018-01-22T20:33:46.91] debugger> ......--> vm.resume()
> [2018-01-22T20:33:46.91] debugger> shouldRunAfterBreakpoint: entered
> [2018-01-22T20:33:46.91] debugger> shouldRunAfterBreakpoint: waiting
> for breakpoint event during 1 sec. [2018-01-22T20:33:46.91]
> debugee.stderr> **> debuggee: 'run': enter :: threadName == thread2
> [2018-01-22T20:33:46.91] debugee.stderr> **> debuggee: 'run': exit ::
> threadName == thread2 [2018-01-22T20:33:46.91] EventHandler> Received
> event set with policy = SUSPEND_ALL [2018-01-22T20:33:46.91]
> EventHandler> Event: BreakpointEventImpl req breakpoint request
> nsk.jdi.EventSet.resume.resume008a:60 (enabled)
> [2018-01-22T20:33:46.91] debugger> Received communication breakpoint
> event. [2018-01-22T20:33:46.91] debugger> shouldRunAfterBreakpoint:
> received breakpoint event. [2018-01-22T20:33:46.91] debugger>
> shouldRunAfterBreakpoint: received instruction from debuggee to
> finish. [2018-01-22T20:33:46.91] debugger> shouldRunAfterBreakpoint:
> exited with false. [2018-01-22T20:33:46.91] debugger> TESTING ENDS
> [2018-01-22T20:33:46.91] debugger> Waiting for debuggee's exit...
> [2018-01-22T20:33:46.91] EventHandler> waitForVMDisconnect
> [2018-01-22T20:33:46.91] debugee.stderr> **> debuggee: debuggee exits
> [2018-01-22T20:33:46.92] EventHandler> Received event set with policy
> = SUSPEND_NONE [2018-01-22T20:33:46.92] EventHandler> Event:
> VMDeathEventImpl req null [2018-01-22T20:33:46.92] EventHandler>
> receieved VMDeath [2018-01-22T20:33:46.92] EventHandler> Removing
> listener nsk.share.jdi.EventHandler$3 at 77f99a05
> [2018-01-22T20:33:47.25] EventHandler> Received event set with policy
> = SUSPEND_NONE [2018-01-22T20:33:47.25] EventHandler> Event:
> VMDisconnectEventImpl req null [2018-01-22T20:33:47.25] EventHandler>
> receieved VMDisconnect [2018-01-22T20:33:47.25] EventHandler> Removing
> listener nsk.share.jdi.EventHandler$4 at 3aeaafa6
> [2018-01-22T20:33:47.25] EventHandler> finished
> [2018-01-22T20:33:47.25] EventHandler> waitForVMDisconnect: done
> [2018-01-22T20:33:47.25] debugger> Event handler thread exited.
> [2018-01-22T20:33:47.25] debugger> Debuggee PASSED.
> [2018-01-22T20:33:47.26] [2018-01-22T20:33:47.26]
> [2018-01-22T20:33:47.26] #> [2018-01-22T20:33:47.26] #> SUMMARY:
> Following errors occured [2018-01-22T20:33:47.26] #> during test
> execution: [2018-01-22T20:33:47.26] #> [2018-01-22T20:33:47.26] #
> ERROR: debugger> ERROR: suspendCounts don't match for : Reference
> Handler [2018-01-22T20:33:47.26] # ERROR: debugger> before resuming :
> 1 [2018-01-22T20:33:47.26] # ERROR: debugger> after resuming : 2
> [2018-01-22T20:33:47.27] # Test level exit status: 97
>
>
> Here's a recent passed log from a local run:
>
> ----------System.out:(164/9808)----------
> run [nsk.jdi.EventSet.resume.resume008, -verbose, -arch=linux-x64,
> -waittime=5, -debugee.vmkind=java, -transport.address=dynamic,
> -debugee.vmkeys=-XX:MaxRAMPercentage=2 ]
> binder> VirtualMachineManager: version 11.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 749dec1a
> binder> Connector arguments:
> binder> home=/export/users/gradams/ws/jdk-jdk/build/linux-x64/images/jdk
> binder> vmexec=java
> binder> options=-XX:MaxRAMPercentage=2
> binder> main=nsk.jdi.EventSet.resume.resume008a "-verbose"
> "-arch=linux-x64" "-waittime=5" "-debugee.vmkind=java"
> "-transport.address=dynamic" "-debugee.vmkeys=-XX:MaxRAMPercentage=2 "
> "-pipe.port=35940"
> binder> quote="
> binder> suspend=true
> binder> Launching debugee
> binder> Waiting for VM initialized
> Initial VMStartEvent received: VMStartEvent in thread main
> EventHandler> Adding listener nsk.share.jdi.EventHandler$1 at 2ab41d39
> EventHandler> Adding listener nsk.share.jdi.EventHandler$2 at 2e3cb1e2
> EventHandler> Adding listener nsk.share.jdi.EventHandler$3 at 57f20df9
> EventHandler> Adding listener nsk.share.jdi.EventHandler$4 at 6e72e291
> EventHandler> Adding listener nsk.share.jdi.EventHandler$5 at 5889e23e
> EventHandler> waitForRequestedEvent: enabling remove of listener
> nsk.share.jdi.EventHandler$6 at 46dcda7f
> EventHandler> Adding listener nsk.share.jdi.EventHandler$6 at 46dcda7f
> EventHandler> waitForRequestedEvent: vm.resume called
> EventHandler> Received event set with policy = SUSPEND_EVENT_THREAD
> EventHandler> Event: ClassPrepareEventImpl req class prepare request
> (enabled)
> EventHandler> waitForRequestedEvent: Received event(ClassPrepareEvent
> in thread main) for request(class prepare request (enabled))
> EventHandler> Removing listener nsk.share.jdi.EventHandler$6 at 46dcda7f
> debugger> Received ClassPrepareEvent for debuggee class:
> nsk.jdi.EventSet.resume.resume008a
> binder> Breakpoint set:
> breakpoint request nsk.jdi.EventSet.resume.resume008a:74 (disabled)
> EventHandler> Adding listener nsk.share.jdi.TestDebuggerType1$1 at 322c2a05
> debugger> TESTING BEGINS
> debugger> RESUME DEBUGGEE VM
> debugger> shouldRunAfterBreakpoint: entered
> debugger> shouldRunAfterBreakpoint: waiting for breakpoint event
> during 1 sec.
>
> debugee.stderr> **> debuggee: debuggee started!
> EventHandler> Received event set with policy = SUSPEND_ALL
> EventHandler> Event: BreakpointEventImpl req breakpoint request
> nsk.jdi.EventSet.resume.resume008a:74 (enabled)
> debugger> Received communication breakpoint event.
>
> debugger> shouldRunAfterBreakpoint: received breakpoint event.
> debugger> shouldRunAfterBreakpoint: exited with true.
> debugger> :::::: case: # 0
> debugger> ......waiting for new ThreadStartEvent : 0
>
> EventHandler> waitForRequestedEventSet: enabling remove of listener
> nsk.share.jdi.EventHandler$7 at 78aa490d
> EventHandler> Adding listener nsk.share.jdi.EventHandler$7 at 78aa490d
> EventHandler> waitForRequestedEventSet: vm.resume called
> EventHandler> Received event set with policy = SUSPEND_NONE
> debugee.stderr> **> debuggee: 'run': enter :: threadName == thread0
> EventHandler> waitForRequestedEventSet: Received event set for
> request: thread start request (enabled)
> EventHandler> Event: ThreadStartEventImpl req thread start request
> (enabled)
> EventHandler> Removing listener nsk.share.jdi.EventHandler$7 at 78aa490d
> EventHandler> Received event set with policy = SUSPEND_ALL
> EventHandler> Event: BreakpointEventImpl req breakpoint request
> nsk.jdi.EventSet.resume.resume008a:74 (enabled)
> debugger> Received communication breakpoint event.
>
> debugger> got new ThreadStartEvent with propety 'number' ==
> ThreadStartRequest1
> debugger> ......checking up on EventSet.resume()
> debugger> ......--> vm.suspend();
> debugger> getting : Map<String, Integer> suspendsCounts1
> debugger> {Reference Handler=2, thread0=2, Common-Cleaner=2, main=2,
> Signal Dispatcher=2, Finalizer=2}
> debugger> eventSet.resume;
> debugger> getting : Map<String, Integer> suspendsCounts2
> debugger> {Reference Handler=2, thread0=2, Common-Cleaner=2, main=2,
> Signal Dispatcher=2, Finalizer=2}
> debugger> getting : int policy = eventSet.suspendPolicy();
> debugger> case SUSPEND_NONE
> debugger> checking Reference Handler
> debugger> checking thread0
> debugger> checking Common-Cleaner
> debugger> checking main
> debugger> checking Signal Dispatcher
> debugger> checking Finalizer
> debugger> ......--> vm.resume()
> debugger> shouldRunAfterBreakpoint: entered
> debugger> shouldRunAfterBreakpoint: received breakpoint event.
> debugger> shouldRunAfterBreakpoint: exited with true.
> debugger> :::::: case: # 1
> debugger> ......waiting for new ThreadStartEvent : 1
> EventHandler> waitForRequestedEventSet: enabling remove of listener
> nsk.share.jdi.EventHandler$7 at 616bc3ae
> EventHandler> Adding listener nsk.share.jdi.EventHandler$7 at 616bc3ae
> EventHandler> waitForRequestedEventSet: vm.resume called
> EventHandler> Received event set with policy = SUSPEND_EVENT_THREAD
> debugee.stderr> **> debuggee: 'run': exit :: threadName == thread0
> EventHandler> waitForRequestedEventSet: Received event set for
> request: thread start request (enabled)
> EventHandler> Event: ThreadStartEventImpl req thread start request
> (enabled)
> EventHandler> Removing listener nsk.share.jdi.EventHandler$7 at 616bc3ae
> debugger> got new ThreadStartEvent with propety 'number' ==
> ThreadStartRequest2
> debugger> ......checking up on EventSet.resume()
> debugger> ......--> vm.suspend();
> debugger> getting : Map<String, Integer> suspendsCounts1
> debugger> {Reference Handler=1, thread1=2, Common-Cleaner=1, main=1,
> Signal Dispatcher=1, Finalizer=1}
> debugger> eventSet.resume;
> debugger> getting : Map<String, Integer> suspendsCounts2
> debugger> {Reference Handler=1, thread1=1, Common-Cleaner=1, main=1,
> Signal Dispatcher=1, Finalizer=1}
> debugger> getting : int policy = eventSet.suspendPolicy();
> debugger> case SUSPEND_THREAD
> debugger> checking Reference Handler
> debugger> checking thread1
> debugger> checking Common-Cleaner
> debugger> checking main
> debugger> checking Signal Dispatcher
> debugger> checking Finalizer
> debugger> ......--> vm.resume()
> debugger> shouldRunAfterBreakpoint: entered
> debugger> shouldRunAfterBreakpoint: waiting for breakpoint event
> during 1 sec.
> debugee.stderr> **> debuggee: 'run': enter :: threadName == thread1
> debugee.stderr> **> debuggee: 'run': exit :: threadName == thread1
> EventHandler> Received event set with policy = SUSPEND_ALL
> EventHandler> Event: BreakpointEventImpl req breakpoint request
> nsk.jdi.EventSet.resume.resume008a:74 (enabled)
> debugger> Received communication breakpoint event.
> debugger> shouldRunAfterBreakpoint: received breakpoint event.
> debugger> shouldRunAfterBreakpoint: exited with true.
> debugger> :::::: case: # 2
> debugger> ......waiting for new ThreadStartEvent : 2
> EventHandler> waitForRequestedEventSet: enabling remove of listener
> nsk.share.jdi.EventHandler$7 at 44e265ef
> EventHandler> Adding listener nsk.share.jdi.EventHandler$7 at 44e265ef
> EventHandler> waitForRequestedEventSet: vm.resume called
> EventHandler> Received event set with policy = SUSPEND_ALL
> EventHandler> waitForRequestedEventSet: Received event set for
> request: thread start request (enabled)
> EventHandler> Event: ThreadStartEventImpl req thread start request
> (enabled)
> EventHandler> Removing listener nsk.share.jdi.EventHandler$7 at 44e265ef
> debugger> got new ThreadStartEvent with propety 'number' ==
> ThreadStartRequest3
> debugger> ......checking up on EventSet.resume()
> debugger> ......--> vm.suspend();
> debugger> getting : Map<String, Integer> suspendsCounts1
> debugger> {Reference Handler=2, thread2=2, Common-Cleaner=2, main=2,
> Signal Dispatcher=2, Finalizer=2}
> debugger> eventSet.resume;
> debugger> getting : Map<String, Integer> suspendsCounts2
> debugger> {Reference Handler=1, thread2=1, Common-Cleaner=1, main=1,
> Signal Dispatcher=1, Finalizer=1}
> debugger> getting : int policy = eventSet.suspendPolicy();
> debugger> case SUSPEND_ALL
> debugger> checking Reference Handler
> debugger> checking thread2
> debugger> checking Common-Cleaner
> debugger> checking main
> debugger> checking Signal Dispatcher
> debugger> checking Finalizer
> debugger> ......--> vm.resume()
> debugger> shouldRunAfterBreakpoint: entered
> debugger> shouldRunAfterBreakpoint: waiting for breakpoint event
> during 1 sec.
> debugee.stderr> **> debuggee: 'run': enter :: threadName == thread2
> debugee.stderr> **> debuggee: 'run': exit :: threadName == thread2
> EventHandler> Received event set with policy = SUSPEND_ALL
> EventHandler> Event: BreakpointEventImpl req breakpoint request
> nsk.jdi.EventSet.resume.resume008a:74 (enabled)
> debugger> Received communication breakpoint event.
> debugger> shouldRunAfterBreakpoint: received breakpoint event.
> debugger> shouldRunAfterBreakpoint: received instruction from debuggee
> to finish.
> debugger> shouldRunAfterBreakpoint: exited with false.
> debugger> TESTING ENDS
> debugger> Waiting for debuggee's exit...
> debugee.stderr> **> debuggee: debuggee exits
> EventHandler> waitForVMDisconnect
> EventHandler> Received event set with policy = SUSPEND_NONE
> EventHandler> Event: VMDeathEventImpl req null
> EventHandler> receieved VMDeath
> EventHandler> Removing listener nsk.share.jdi.EventHandler$3 at 57f20df9
> EventHandler> Received event set with policy = SUSPEND_NONE
> EventHandler> Event: VMDisconnectEventImpl req null
> EventHandler> receieved VMDisconnect
> EventHandler> Removing listener nsk.share.jdi.EventHandler$4 at 6e72e291
> EventHandler> finished
> EventHandler> waitForVMDisconnect: done
> debugger> Event handler thread exited.
> debugger> Debuggee PASSED.
>
> On 7/18/18, 6:09 PM, gary.adams at oracle.com wrote:
>> On 7/18/18 4:47 PM, Chris Plummer wrote:
>>> Hi Gary
>>>
>>> Ok, so shouldRunAfterBreakpoint() is the code that does the
>>> eventHandler.wait(), so it gets the eventHandler.notifyAll()
>>> notification from the BreakpointEvent handler.
>>>
>>> And as a side note, I see now that resumption of execution after the
>>> breakpoint at main() is done by:
>>>
>>> // after waitForClassPrepared() main debuggee thread is
>>> suspended, resume it before test start
>>> display("RESUME DEBUGGEE VM");
>>> vm.resume();
>>>
>>> testRun();
>>>
>>> shouldRunAfterBreakpoint() is returning true until the end of the
>>> test when the debuggee is executes "instruction = end". That's why
>>> runTests() does a "break" when shouldRunAfterBreakpoint() returns
>>> false. So this means the code that is checking
>>> shouldRunAfterBreakpoint() is not resuming execution for the first
>>> few (probably 3) methodForCommunication() breakpoints. However, it
>>> does make sure that runTests() blocks until the BreakPointEvent has
>>> been processed.
>>>
>>> You point out the vm.resume() at the bottom of the loop in
>>> runTests(), but that's only after a bunch of ThreadStartEvent
>>> processing above it has been done already. The ThreadStartEvent
>>> would never get generated if there was not a resume some point
>>> earlier. I think it is happening during the
>>> eventHandler.waitForRequestedEventSet() call, which does a vm.resume().
>>>
>>> So if I understand the order of things now:
>>>
>>> -shouldRunAfterBreakpoint() returns after first
>>> methodForCommunication() is hit. At this point we know the first
>>> thread has been created, but no attempt to start it yet. The
>>> debuggee is suspended at this point.
>>> -runTests() requests ThreadStartEvents with SUSPEND_NONE. This also
>>> does a vm.resume().
>>> -The debuggee starts the thread and then does another
>>> methodForCommunication() (this 2nd one is actually after the 2nd
>>> thread has been created, but not yet started). Now we have a race.
>>> Do we get the ThreadStartEvent first or the BreakpointEvent. This is
>>> because when the ThreadStartEvent is generated, the thread is not
>>> suspended due to SUSPEND_NONE. Even if the ThreadStartEvent comes in
>>> first, the async handling of the BreakpointEvent can cause problems
>>> during the ThreadStartEvent processing.
>> Based on the failed log in the bug report, the thread start event is
>> observed,
>> the suspend counts acquired, then after the resume, the breakpoint
>> message
>> is displayed and the second set of suspend counts acquired.
>>
>> I can show you the passed and failed logs tomorrow.
>>> -You added a 100ms delay after the thread has started, but before
>>> methodForCommunication(), hoping it will make it so the
>>> ThreadStartEvent can be received and fully processed before the
>>> BreakpointEvent is.
>> The delay is mostly just a yield so the debugger gets a chance to run.
>>>
>>> I think it would be preferable to fix this by doing better
>>> sychronization. After all, that is the approach the test originally
>>> took. It could have been written with a bunch of sleep() delays
>>> instead, but that in general is not a very good approach.
>>>
>>> What if you added a shouldRunAfterBreakpoint() call after getting
>>> the ThreadStartEvent arrives. At this point you would know that the
>>> vm is suspended due to the breakpoint, so no need for:
>>>
>>> display("......checking up on EventSet.resume()");
>>> display("......--> vm.suspend();");
>>> vm.suspend();
>> I think the suspend is intentional to capture the the suspend counts.
>> It also needs to resume the vm and acquire again so it can confirm
>> the correct
>> suspend count behaviors.
>> If the test waits to capture the second set of suspend counts, the
>> breakpoint
>> causes incorrect values.
>>
>> ...
>>>
>>> You might then also need to add another methodForCommunication()
>>> call at the end of case 0 and 1 in the debuggee, although I think
>>> you could instead just change the shouldRunAfterBreakpoint() at the
>>> start of the loop. I think that check actually belongs at the end of
>>> the loop, and only for case 2. In fact it would be an error if
>>> shouldRunAfterBreakpoint() did not return true in that case. Then
>>> you also need to add a shouldRunAfterBreakpoint() at the start of
>>> case 0 to get things rolling (and I think at the start of case 1 also).
>>>
>>> Chris
>>>
>>>
>>> On 7/18/18 12:45 PM, Gary Adams wrote:
>>>> Answers below ...
>>>>
>>>> On 7/18/18, 2:50 PM, Chris Plummer wrote:
>>>>> Hi Gary,
>>>>>
>>>>> Who does the resume for the breakpoint event?
>>>>>
>>>>> eventHandler.addListener(
>>>>> new EventHandler.EventListener() {
>>>>> public boolean eventReceived(Event event) {
>>>>> if (event instanceof BreakpointEvent &&
>>>>> bpRequest.equals(event.request())) {
>>>>> synchronized(eventHandler) {
>>>>> display("Received communication
>>>>> breakpoint event.");
>>>>> bpCount++;
>>>>> eventHandler.notifyAll();
>>>>> }
>>>>> return true;
>>>>> }
>>>>> return false;
>>>>> }
>>>>> }
>>>>> );
>>>> I believe you are looking for this sequence.
>>>> At the top of the loop a check is made if
>>>> resume() should be called "shouldRunAfterBreakpoint".
>>>> lines 96-99 is an early termination. And at the
>>>> bottom of the loop, line 240, is the normal
>>>> continue the test to the next case.
>>>>
>>>> resume008.java :
>>>> ...
>>>> 94 for (int i = 0; ; i++) {
>>>> 95
>>>>
>>>> 96 if (!shouldRunAfterBreakpoint()) {
>>>> 97 vm.resume();
>>>> 98 break;
>>>> 99 }
>>>>
>>>> 100
>>>> 101
>>>> 102 display(":::::: case: # " + i);
>>>> 103
>>>> 104 switch (i) {
>>>> 105
>>>> 106 case 0:
>>>> 107 eventRequest = settingThreadStartRequest (
>>>> 108 SUSPEND_NONE, "ThreadStartRequest1");
>>>> ...
>>>> 238
>>>> 239 display("......--> vm.resume()");
>>>> 240 vm.resume();
>>>> 241 }
>>>>>
>>>>> Also:
>>>>>
>>>>>> 1. On a thread start event the debugee is suspended, line 141
>>>>> That's not true for the first ThreadStartEvent since SUSPEND_NONE
>>>>> was used.
>>>> The thread start event is set to SUSPEND_NONE for thread0, but when
>>>> the thread start event is observed the resume008 test suspends the vm
>>>> immediately after fetching the "number" property.
>>> My point is that the Debuggee continues to run after the
>>> ThreadStartEvent is sent, and relies on the debugger to stop it
>>> after receiving the event. But in the meantime the debuggee has
>>> advanced to the next breakpoint, but only sometimes, thus the bug
>>> you are seeing.
>>>>
>>>> 132 if ( !(newEvent instanceof ThreadStartEvent)) {
>>>> 133 setFailedStatus("ERROR: new event is not
>>>> ThreadStartEvent");
>>>> 134 } else {
>>>> 135
>>>> 136 String property = (String)
>>>> newEvent.request().getProperty("number");
>>>> 137 display(" got new ThreadStartEvent
>>>> with propety 'number' == " + property);
>>>> 138
>>>> 139 display("......checking up on
>>>> EventSet.resume()");
>>>> 140 display("......--> vm.suspend();");
>>>> 141 vm.suspend();
>>>>
>>>>
>>>>>
>>>>> Chris
>>>>>
>>>>> On 7/18/18 4:52 AM, Gary Adams wrote:
>>>>>> There is nothing wrong with the breakpoint in
>>>>>> methodForCommunication.
>>>>>> The test uses it to make sure the threads are each tested
>>>>>> separately.
>>>>>> The breakpoint eventhandler just displays a message, increments a
>>>>>> counter
>>>>>> and returns.
>>>>>>
>>>>>> Let me step through resume008a the debugee to help clarify ...
>>>>>>
>>>>>> 1. The test thread is created and the synchronized break point is
>>>>>> observed. lines 101-102
>>>>>> 2. The thread is started. lines 104,135-137
>>>>>> 2a. The main thread blocks on a local object. lines 133, 139
>>>>>> 2b. The test thread is started. lines 137,
>>>>>> A run entered message is displayed, line 159
>>>>>> The main thread lock object is notified, line 167
>>>>>> 2b1. The main thread continues. line 167, 146
>>>>>> The next test thread is created. line 106
>>>>>> The synchronized breakpoint is observed, line 107
>>>>>> 2b2. A run exited message is displayed, line 169
>>>>>>
>>>>>> On the resume008 debugger side ...
>>>>>> 1. On a thread start event the debugee is suspended, line 141
>>>>>> 2. Messages are displayed and a first set of thread suspend
>>>>>> counts is acquired. lines 143-151
>>>>>> 3. The threads are resumed, line 152
>>>>>> --->
>>>>>> 4. Messages are displayed and a second set of thread suspend
>>>>>> counts is acquired. lines 154-159
>>>>>>
>>>>>> The way the test is written the expectation is the debugger steps
>>>>>> 2,3,4 will all happen
>>>>>> while the test thread is running.
>>>>>>
>>>>>> When the debugger resumes the debuggee threads (debugger step 3)
>>>>>> the debuggee continues from where it left off (debuggee steps
>>>>>> 2b,2b1,2b2)
>>>>>>
>>>>>> If we complete debuggee step 2b1 (line 107) before the debugger
>>>>>> completes step 4 line 159,
>>>>>> then the synchronized breakpoint will suspend the vm and the
>>>>>> counts will not match
>>>>>> for the SUSPEND_NONE test thread start.
>>>>>>
>>>>>> resume008a.java:
>>>>>>
>>>>>> 100 case 0:
>>>>>> 101 thread0 = new
>>>>>> Threadresume008a("thread0");
>>>>>> 102 methodForCommunication();
>>>>>> 103
>>>>>> 104 threadStart(thread0);
>>>>>> 105
>>>>>> 106 thread1 = new
>>>>>> Threadresume008a("thread1");
>>>>>> 107 methodForCommunication();
>>>>>> 108 break;
>>>>>>
>>>>>> ...
>>>>>> 135 static int threadStart(Thread t) {
>>>>>> 136 synchronized (waitnotifyObj) {
>>>>>> 137 t.start();
>>>>>> 138 try {
>>>>>> 139 waitnotifyObj.wait();
>>>>>> 140 } catch ( Exception e) {
>>>>>> 141 exitCode = FAILED;
>>>>>> 142 logErr(" Exception : " + e );
>>>>>> 143 return FAILED;
>>>>>> 144 }
>>>>>> 145 }
>>>>>> 146 return PASSED;
>>>>>> 147 }
>>>>>>
>>>>>> 149 static class Threadresume008a extends Thread {
>>>>>> ...
>>>>>> 157
>>>>>> 158 public void run() {
>>>>>> 159 log1(" 'run': enter :: threadName == " +
>>>>>> tName);
>>>>>>
>>>>>> This is the proposed fix that will let the debugger complete it's
>>>>>> second
>>>>>> acquisition of suspend counts while the test thread is still
>>>>>> running.
>>>>>>
>>>>>> 160 // Yield, so the start thread event
>>>>>> processing can be completed.
>>>>>> 161 try {
>>>>>> 162 Thread.sleep(100);
>>>>>> 163 } catch (InterruptedException e) {
>>>>>> 164 // ignored
>>>>>> 165 }
>>>>>>
>>>>>> 166 synchronized (waitnotifyObj) {
>>>>>> 167 waitnotifyObj.notify();
>>>>>> 168 }
>>>>>> 169 log1(" 'run': exit :: threadName == " +
>>>>>> tName);
>>>>>> 170 return;
>>>>>> 171 }
>>>>>> 172 }
>>>>>> 150
>>>>>> 151 String tName = null;
>>>>>> 152
>>>>>> 153 public Threadresume008a(String threadName) {
>>>>>> 154 super(threadName);
>>>>>> 155 tName = threadName;
>>>>>> 156 }
>>>>>> 157
>>>>>> 158 public void run() {
>>>>>> 159 log1(" 'run': enter :: threadName == " +
>>>>>> tName);
>>>>>> 160 // Yield, so the start thread event
>>>>>> processing can be completed.
>>>>>> 161 try {
>>>>>> 162 Thread.sleep(100);
>>>>>> 163 } catch (InterruptedException e) {
>>>>>> 164 // ignored
>>>>>> 165 }
>>>>>> 166 synchronized (waitnotifyObj) {
>>>>>> 167 waitnotifyObj.notify();
>>>>>> 168 }
>>>>>> 169 log1(" 'run': exit :: threadName == " +
>>>>>> tName);
>>>>>> 170 return;
>>>>>> 171 }
>>>>>> 172 }
>>>>>>
>>>>>>
>>>>>>
>>>>>> On 7/18/18, 2:38 AM, Chris Plummer wrote:
>>>>>>> Hi Gary,
>>>>>>>
>>>>>>> I've been having trouble following the control flow of this
>>>>>>> test. One thing I've stumbled across is the following:
>>>>>>>
>>>>>>> /* A debuggee class must define
>>>>>>> 'methodForCommunication'
>>>>>>> * method and invoke it in points of synchronization
>>>>>>> * with a debugger.
>>>>>>> */
>>>>>>> setCommunicationBreakpoint(debuggeeClass,"methodForCommunication");
>>>>>>>
>>>>>>> So why isn't this mode of synchronization good enough? Is it
>>>>>>> because it was not designed with the understanding that the
>>>>>>> debugger might be doing suspended thread counts, and suspending
>>>>>>> all threads at the breakpoint messes up the test?
>>>>>>>
>>>>>>> From what I can tell of the test, after the debuggee is started
>>>>>>> and hits the default breakpoint at the start of main(), the
>>>>>>> debugger then does a vm.resume() at the start of the for loop in
>>>>>>> the runTest() method. The debuggee then creates a thread and
>>>>>>> calls methodForCommunication(). There is already a breakpoint
>>>>>>> set there by the above debuggee code. It's unclear to me what
>>>>>>> happens as a result of this breakpoint and how it serves the
>>>>>>> test. Also unclear to me who is responsible for the vm.resume()
>>>>>>> after the breakpoint is hit.
>>>>>>>
>>>>>>> The debugger then requests all ThreadStart events, requesting
>>>>>>> that no threads be disabled when it is sent. I think you are
>>>>>>> saying that when the ThreadStart event comes in, sometimes we
>>>>>>> are at the methodForCommunication breakpoint, with all threads
>>>>>>> disabled, and this messes up the thread suspend counts. You want
>>>>>>> to delay 100ms so the breakpoint event can be processed and
>>>>>>> threads resumed again (although I can't see who actually resumes
>>>>>>> the thread after hitting the methodForCommunication breakpoint).
>>>>>>>
>>>>>>> Chris
>>>>>>>
>>>>>>> On 7/17/18 8:33 AM, Gary Adams wrote:
>>>>>>>> A race condition exists between the debugger and the debuggee.
>>>>>>>>
>>>>>>>> The first test thread is started with SUSPEND_NONE policy set.
>>>>>>>> While processing the thread start event the debugger captures
>>>>>>>> an initial set of thread suspend counts and resumes the
>>>>>>>> debuggee vm. If the debuggee advances quickly it reaches
>>>>>>>> the breakpoint set for methodForCommunication. Since the
>>>>>>>> breakpoint
>>>>>>>> carries with it SUSPEND_ALL policy, when the debugger captures
>>>>>>>> a second
>>>>>>>> set of suspend counts, it will not match the expected counts for
>>>>>>>> a SUSPEND_NONE scenario.
>>>>>>>>
>>>>>>>> The proposed fix introduces a yield in the debuggee test thread
>>>>>>>> run method
>>>>>>>> to allow the debugger to get the expected sampled values.
>>>>>>>>
>>>>>>>> Issue: https://bugs.openjdk.java.net/browse/JDK-8170089
>>>>>>>> Webrev: http://cr.openjdk.java.net/~gadams/8170089/webrev.00/
>>>>>>>>
>>>>>>>>
>>>>>>>> test/hotspot/jtreg/vmTestbase/nsk/share/jdi/TestDebuggerType1.java:
>>>>>>>>
>>>>>>>> ...
>>>>>>>> 186 private void
>>>>>>>> setCommunicationBreakpoint(ReferenceType refType, String
>>>>>>>> methodName) {
>>>>>>>> 187 Method method =
>>>>>>>> debuggee.methodByName(refType, methodName);
>>>>>>>> 188 Location location = null;
>>>>>>>> 189 try {
>>>>>>>> 190 location = method.allLineLocations().get(0);
>>>>>>>> 191 } catch (AbsentInformationException e) {
>>>>>>>> 192 throw new Failure(e);
>>>>>>>> 193 }
>>>>>>>> 194 bpRequest = debuggee.makeBreakpoint(location);
>>>>>>>> 195
>>>>>>>>
>>>>>>>> 196 bpRequest.setSuspendPolicy(EventRequest.SUSPEND_ALL);
>>>>>>>>
>>>>>>>> 197 bpRequest.putProperty("number", "zero");
>>>>>>>> 198 bpRequest.enable();
>>>>>>>> 199
>>>>>>>> 200 eventHandler.addListener(
>>>>>>>> 201 new EventHandler.EventListener() {
>>>>>>>> 202 public boolean eventReceived(Event
>>>>>>>> event) {
>>>>>>>> 203 if (event instanceof
>>>>>>>> BreakpointEvent && bpRequest.equals(event.request())) {
>>>>>>>> 204 synchronized(eventHandler) {
>>>>>>>> 205 display("Received communication breakpoint event.");
>>>>>>>> 206 bpCount++;
>>>>>>>> 207 eventHandler.notifyAll();
>>>>>>>> 208 }
>>>>>>>> 209 return true;
>>>>>>>> 210 }
>>>>>>>> 211 return false;
>>>>>>>> 212 }
>>>>>>>> 213 }
>>>>>>>> 214 );
>>>>>>>> 215 }
>>>>>>>>
>>>>>>>>
>>>>>>>> test/hotspot/jtreg/vmTestbase/nsk/jdi/EventSet/resume/resume008.java:
>>>>>>>>
>>>>>>>> ...
>>>>>>>> 140 display("......--> vm.suspend();");
>>>>>>>> 141 vm.suspend();
>>>>>>>> 142
>>>>>>>> 143 display(" getting :
>>>>>>>> Map<String, Integer> suspendsCounts1");
>>>>>>>> 144
>>>>>>>> 145 Map<String, Integer> suspendsCounts1
>>>>>>>> = new HashMap<String, Integer>();
>>>>>>>> 146 for (ThreadReference threadReference
>>>>>>>> : vm.allThreads()) {
>>>>>>>> 147 suspendsCounts1.put(threadReference.name(),
>>>>>>>> threadReference.suspendCount());
>>>>>>>> 148 }
>>>>>>>> 149 display(suspendsCounts1.toString());
>>>>>>>> 150
>>>>>>>> 151 display(" eventSet.resume;");
>>>>>>>> 152 eventSet.resume();
>>>>>>>> 153
>>>>>>>> 154 display(" getting :
>>>>>>>> Map<String, Integer> suspendsCounts2");
>>>>>>>>
>>>>>>>> This is where the breakpoint is encountered before the second
>>>>>>>> set of suspend counts is acquired.
>>>>>>>>
>>>>>>>> 155 Map<String, Integer> suspendsCounts2
>>>>>>>> = new HashMap<String, Integer>();
>>>>>>>> 156 for (ThreadReference threadReference
>>>>>>>> : vm.allThreads()) {
>>>>>>>> 157 suspendsCounts2.put(threadReference.name(),
>>>>>>>> threadReference.suspendCount());
>>>>>>>> 158 }
>>>>>>>> 159 display(suspendsCounts2.toString());
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>
More information about the serviceability-dev
mailing list