Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-6902121

intermittent JdbMethodExitTest timeout

XMLWordPrintable

    • x86
    • solaris_10

      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.

            Unassigned Unassigned
            dcubed Daniel Daugherty
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved:
              Imported:
              Indexed: