RFR JDK-8170089: nsk/jdi/EventSet/resume/resume008: ERROR: suspendCounts don't match for : Common-Cleaner
Gary Adams
gary.adams at oracle.com
Thu Jul 19 12:08:12 UTC 2018
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());
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/serviceability-dev/attachments/20180719/c20bfffa/attachment-0001.html>
More information about the serviceability-dev
mailing list