During my baseline testing of the following JDK promotion:
java version "1.7.0-ea"
Java(TM) SE Runtime Environment (build 1.7.0-ea-b76)
Java HotSpot(TM) Server VM (build 17.0-b05, mixed mode)
the following JDI_REGRESSION test timed out:
RULE com/sun/jdi/JdbMethodExitTest.sh Timeout any
on my Solaris X86 test machine:
% uname -a
SunOS oliver-gs 5.10 Generic_137138-09 i86pc i386 i86pc
% psrinfo -v
Status of virtual processor 0 as of: 11/17/2009 10:19:53
on-line since 10/03/2009 21:14:48.
The i386 processor operates at 2800 MHz,
and has an i387 compatible floating point processor.
Status of virtual processor 1 as of: 11/17/2009 10:19:53
on-line since 10/03/2009 21:15:03.
The i386 processor operates at 2800 MHz,
and has an i387 compatible floating point processor.
The .jtr timestamps show the previous tests and following
tests executed quickly:
-rw-rw-r-- 1 dcubed green 1628 Nov 13 18:20 JdbArgTest.jtr
-rw-rw-r-- 1 dcubed green 3347 Nov 13 18:20 JdbLockTest.jtr
drwxrwxr-x 2 dcubed green 512 Nov 13 18:20 JdbMethodExitTest/
-rw-rw-r-- 1 dcubed green 25436 Nov 13 18:21 JdbMethodExitTest.jtr
-rw-rw-r-- 1 dcubed green 3335 Nov 13 18:21 JdbMissStep.jtr
/var/adm/messages showed no messages during this time frame.
Since these were product JDK and product VM bits, this test
shouldn't have timed out.
I've attached the complete .jtr file, but here are some
observations about the failure:
- the test was executing the following block in
test/com/sun/jdi/JdbMethodExitTest.sh:
268 cmd step # step into traceExit()
269 cmd trace method exit
270 cmd cont
271 jdbFailIfNotPresent "Method exited: return value = \"traceExit\""
272 cmd untrace
273 cmd step up
274
275
276 cmd step
277 cmd step # skip over setting return value in caller :-(
278 cmd trace go method exit
279 cmd cont
280 jdbFailIfNotPresent 'Method exited: .*JdbMethodExitTest.traceExit1'
281 cmd quit
The test had just finished the "traceExit" test and was starting
on the "traceExit1" test which is the last test section. So the
test had just finished line 276 and was starting line 277.
- the last few commands sent by the test script are:
trace method exit
cont
untrace
step up
step
- the test output shows the results of the above commands:
main[1] main[1] >
Method exited: return value = "traceExit", "thread=main", JdbMethodExitTest.traceExit(), line=104 bci=2
104 return "traceExit";
main[1] main[1] >
Step completed: "thread=main", JdbMethodExitTest.main(), line=139 bci=43
139 traceExit();
main[1]
Step completed: "thread=main", JdbMethodExitTest.main(), line=142 bci=44
142 traceExit1();
main[1] > Input stream closed.
- the TestScaffold detected that the test was stuck; the jstack output
shows something interesting:
----------------- t@2 -----------------
0xfeec9455 ___lwp_cond_wait + 0x15
0xfea3998e void os::PlatformEvent::park() + 0xb2
0xfea20f39 int ParkCommon(ParkEvent*,long long) + 0x59
0xfea2148d int Monitor::IWait(Thread*,long long) + 0xa5
0xfea21d3a bool Monitor::wait(bool,long,bool) + 0x256
0xfeb2f004 int JavaThread::java_suspend_self() + 0xe0
0xfeb0fb78 int ObjectMonitor::raw_wait(long long,bool,Thread*) + 0x140
0xfe95669e jvmtiError JvmtiEnv::RawMonitorWait(JvmtiRawMonitor*,long long)
+ 0xde
0xfe8f4531 jvmti_RawMonitorWait + 0x139
0xfe14972d debugMonitorWait + 0x31
0xfe13959d enqueueCommand + 0x14d
0xfe13acdc eventHelper_reportEvents + 0xf0
0xfe135505 reportEvents + 0x131
0xfe135a35 event_callback + 0x345
0xfe135dbb cbSingleStep + 0x11b
0xfe9661ca void JvmtiExport::post_single_step(JavaThread*,methodOopDesc*,unsigned char*) + 0x67a
0xfe9619fd void JvmtiExport::at_single_stepping_point(JavaThread*,methodOopDesc*,unsigned char*) + 0x195
0xfe5f4d68 void InterpreterRuntime::at_safepoint(JavaThread*) + 0x250
0xfb00b9ae * JdbMethodExitTest.main(java.lang.String[]) bci:44 line:142 (Interpreted frame)
0xfb000348 <StubRoutines>
0xfe51ea36 void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*) + 0x1c2
0xfe51ece7 void os::os_exception_wrapper(void(*)(JavaValue*,methodHandle*,JavaCallArguments*,Thread*),JavaValue*,methodHandle*,JavaCallArguments*,Thread*)
+ 0x17
0xfe51ed1b void JavaCalls::call(JavaValue*,methodHandle,JavaCallArguments*,Thread*) + 0x2f
0xfe5ab1cc void jni_invoke_static(JNIEnv_*,JavaValue*,_jobject*,JNICallType,_jmethodID*,JNI_ArgumentPusher*,Thread*) + 0xe8
0xfe5b51bb jni_CallStaticVoidMethod + 0x97
0xfef734af JavaMain + 0x88f
0xfeec59b9 _thr_setup + 0x4e
0xfeec5ca0 _lwp_start
The thread that is posting a single step event has self suspended
due to a external suspend request. This might be part of the usual
single-step implementation and not an indication of a problem; I
have some vague memories that single stepping uses suspend/resume
combined with InterpreterRuntime::at_safepoint() in order to make
sure that each bytecode is stepped.