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

methodOopDesc::jmethod_id() can deadlock when used by the VMThread

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: P2 P2
    • 6
    • 6
    • hotspot
    • 6
    • b93
    • generic
    • generic

      During Suspend/Resume stress testing of the fix for 6440070 over the
      July 4th Shutdown on Solaris SPARC Client and Server VMs, there were
      many failed runs due to a hang:

      producer-c1-fast/CPUSampling/save.6440070/doit_loop.log: 1 hang
      producer-c1-fast/PepTest/save.6440070/doit_loop.log: 7 hangs
      producer-c1-jvmg/Java2Demo/save.6440070/doit_loop.log: 1 hang
      producer-c1-jvmg/PepTest/save.6440070/doit_loop.log: 1 hang
      producer-c1-prod/Java2Demo/save.6440070/doit_loop.log: 1 hang
      producer-c1-prod/PepTest/save.6440070/doit_loop.log: 15 hangs

      I have attached a sample hang as threads.log.207 and I have included
      the stack traces for the interesting threads below.

      This failure looks like a classic deadlock. Thread t@2 called
      methodOopDesc::jmethod_id() and blocked on a safepoint trying to
      acquire JNIGlobalHandle_lock while holding the JNIIdentifier_lock.
      Thread t@8 called JVM/TI GetThreadListStackTraces() which resulted in a
      VM operation so thread t@3 (VMThread) called methodOopDesc::jmethod_id()
      while trying to get a stack trace at a safepoint. The VMThread blocks
      on JNIIdentifier_lock and we have a deadlock.


      THREAD t@2

      The thread is posting a ClassLoad event and the event handler calls
      JVM/TI GetStackTrace(). While trying to fill in the stack trace info,
      this thread blocks on a safepoint.

      t@2 (l@2) stopped in ___lwp_mutex_lock at 0xff29f990
      0xff29f990: ___lwp_mutex_lock+0x0008: ta 8
      current thread: t@2
        [1] ___lwp_mutex_lock(0xa66a0, 0x52800, 0xad318, 0x529bd, 0xd8c284, 0x52800), at 0xff29f990
      =>[2] Mutex::lock_without_safepoint_check(this = ???) (optimized), at 0xfe276c1c (line ~294) in "os_solaris.hpp"
        [3] SafepointSynchronize::block(thread = ???) (optimized), at 0xfe38b980 (line ~582) in "safepoint.cpp"
        [4] Mutex::wait_for_lock_blocking_implementation(this = ???, thread = ???) (optimized), at 0xfe27b93c (line ~299) in "os_solaris.hpp"
        [5] Mutex::lock(this = ???, thread = ???) (optimized), at 0xfe276558 (line ~124) in "mutex.cpp"
        [6] JNIHandles::make_jmethod_id(mh = CLASS) (optimized), at 0xfde649a4 (line ~88) in "jniHandles.cpp"
          make_jmethod_id() tries to grab the JNIGlobalHandle_lock and
          blocks on the safepoint.

        [7] instanceKlass::jmethod_id_for_impl(ik_h = CLASS, method_h = CLASS) (optimized), at 0xfdc77c20 (line ~972) in "instanceKlass.cpp"
          jmethod_id_for_impl() grabs the JNIIdentifier_lock before it calls
          make_jmethod_id().

        [8] methodOopDesc::jmethod_id(this = ???) (optimized), at 0xfdb44fcc (line ~27) in "klassOop.hpp"
        [9] JvmtiEnvBase::get_stack_trace(this = ???, java_thread = ???, start_depth = ???, max_count = ???, frame_buffer = ???, count_ptr = ???) (optimized), at 0xfe0fd68c (line ~682) in "jvmtiEnvBase.cpp"
        [10] JvmtiEnv::GetStackTrace(this = ???, java_thread = ???, start_depth = ???, max_frame_count = ???, frame_buffer = ???, count_ptr = ???) (optimized), at 0xfe0e17dc (line ~789) in "jvmtiEnv.cpp"
        [11] jvmti_GetStackTrace(env = ???, thread = ???, start_depth = ???, max_frame_count = ???, frame_buffer = ???, count_ptr = ???) (optimized), at 0xfdf84820 (line ~1130) in "jvmtiEnter.cpp"
        [12] getStackTrace(0xfdf83430, 0xff08cca0, 0xfd6cc5e0, 0xfd67e67c, 0x800, 0x1540c), at 0xfd6b6d4c
        [13] trace_get_current(0x148b14, 0x30d41, 0x4, 0x0, 0x1464b8, 0x16cf30), at 0xfd6b16bc
        [14] get_trace(0x148b14, 0x30d41, 0x4, 0x0, 0x1464b8, 0x16cf30), at 0xfd6aeb84
        [15] tls_get_trace(0x30000001, 0xa8104, 0x4, 0x0, 0x800, 0x1bb50), at 0xfd6b0630
        [16] event_class_load(0xa8104, 0x1488c4, 0x1488c8, 0x0, 0x90000001, 0x34bfc), at 0xfd6975d8
        [17] cbClassLoad(0xfd6cc5e0, 0xa8104, 0x1488c4, 0x1488c8, 0xfd6cc94c, 0xa8aa0), at 0xfd69dca8
        [18] JvmtiExport::post_class_load(thread = ???, klass = CLASS) (optimized), at 0xfe116070 (line ~780) in "jvmtiExport.cpp"
        [19] SystemDictionary::define_instance_class(k = CLASS, __the_thread__ = ???) (optimized), at 0xfe41feac (line ~1277) in "systemDictionary.cpp"
        [20] SystemDictionary::load_instance_class(class_name = CLASS, class_loader = CLASS, __the_thread__ = ???) (optimized), at 0xfe41df7c (line ~1169) in "systemDictionary.cpp"
        [21] SystemDictionary::resolve_instance_class_or_null(class_name = CLASS, class_loader = CLASS, protection_domain = CLASS, __the_thread__ = ???) (optimized), at 0xfe4172e4 (line ~733) in "systemDictionary.cpp"
        [22] SystemDictionary::resolve_or_null(class_name = CLASS, class_loader = CLASS, protection_domain = CLASS, __the_thread__ = ???) (optimized), at 0xfe411e70 (line ~206) in "systemDictionary.cpp"
        [23] SystemDictionary::resolve_or_fail(class_name = CLASS, class_loader = CLASS, protection_domain = CLASS, throw_error = ???, __the_thread__ = ???) (optimized), at 0xfe410fb4 (line ~155) in "systemDictionary.cpp"
        [24] constantPoolOopDesc::klass_at_impl(this_oop = CLASS, which = ???, __the_thread__ = ???) (optimized), at 0xfdb9ef0c (line ~61) in "constantPoolOop.cpp"
        [25] InterpreterRuntime::_new(thread = ???, pool = ???, index = ???) (optimized), at 0xfdccff58 (line ~206) in "constantPoolOop.hpp"
        [26] 0xfb42eefc(0xf30254d0, 0x8, 0xff0a2174, 0xfb420f20, 0x0, 0xfd67f760), at 0xfb42eefb
        [27] 0xfb405a10(0xf30254d0, 0x8, 0xff0a2174, 0xfb42db00, 0x0, 0xfd67f7f0), at 0xfb405a0f
        [28] 0xfb4058a8(0xf30254d0, 0x8, 0xff0a2174, 0xfb42dee0, 0x0, 0xfd67f880), at 0xfb4058a7
        [29] 0xfb4058a8(0x4a000, 0x8, 0xff0a2174, 0xfb42db00, 0x0, 0xfd67f900), at 0xfb4058a7
        [30] 0xfb4058a8(0x4a000, 0x8, 0xff0a2174, 0xfb42e3f0, 0x0, 0xfd67f998), at 0xfb4058a7
        [31] 0xfb4058a8(0xf30254b8, 0x8, 0xff0a2174, 0xfb42e390, 0x0, 0xfd67fa28), at 0xfb4058a7
        [32] 0xfb405a10(0x17, 0x2c970, 0x16, 0xfb42dee0, 0xfd67fd59, 0xfd67fab0), at 0xfb405a0f
        [33] 0xfb4002d0(0xfd67fbb8, 0xfd67fee8, 0xa, 0xf7008ff0, 0xfb4121c0, 0xfd67fd00), at 0xfb4002cf
        [34] JavaCalls::call_helper(result = ???, m = ???, args = ???, __the_thread__ = ???) (optimized), at 0xfdd0e20c (line ~367) in "javaCalls.cpp"
        [35] jni_invoke_nonstatic(env = ???, result = ???, receiver = ???, call_type = ???, method_id = ???, args = ???, __the_thread__ = ???) (optimized), at 0xfdd55a1c (line ~1054) in "jni.cpp"
        [36] jni_NewObject(env = ???, clazz = ???, methodID = ???, ...) (optimized), at 0xfdd598b4 (line ~1131) in "jni.cpp"
        [37] JavaMain(0x0, 0x2b32c, 0x2ac30, 0xa91b8, 0xffbef03e, 0x2ac22), at 0x13218

      THREAD t@3

      This is the VMThread and it is handling a VM operation in response to
      thread t@8's JVM/TI GetThreadListStackTraces() call. While trying to
      fill in the stack trace info, this thread blocks trying to acquire a
      lock.

      t@3 (l@3) stopped in ___lwp_mutex_lock at 0xff29f990
      0xff29f990: ___lwp_mutex_lock+0x0008: ta 8
      current thread: t@3
        [1] ___lwp_mutex_lock(0xa7140, 0x52800, 0xad318, 0x529bd, 0xd8c284, 0x52800), at 0xff29f990
      =>[2] os::Solaris::Event::lock(this = ???) (optimized), at 0xfe277cc0 (line ~294) in "os_solaris.hpp"
        [3] Mutex::lock(this = ???, thread = ???) (optimized), at 0xfe276518 (line ~120) in "mutex.cpp"
        [4] instanceKlass::jmethod_id_for_impl(ik_h = CLASS, method_h = CLASS) (optimized), at 0xfdc770dc (line ~943) in "instanceKlass.cpp"
        [5] methodOopDesc::jmethod_id(this = ???) (optimized), at 0xfdb44fcc (line ~27) in "klassOop.hpp"
          jmethod_id_for_impl() tries to grab the JNIIdentifier_lock, but it
          blocks because thread t@2 is holding it.

        [6] JvmtiEnvBase::get_stack_trace(this = ???, java_thread = ???, start_depth = ???, max_count = ???, frame_buffer = ???, count_ptr = ???) (optimized), at 0xfe0fd68c (line ~682) in "jvmtiEnvBase.cpp"
        [7] VM_GetThreadListStackTraces::doit(this = ???) (optimized), at 0xfe100750 (line ~1038) in "jvmtiEnvBase.cpp"
        [8] VM_Operation::evaluate(this = ???) (optimized), at 0xfe5bb2cc (line ~25) in "vm_operations.cpp"
        [9] VMThread::evaluate_operation(this = ???, op = ???) (optimized), at 0xfe5b94d4 (line ~314) in "vmThread.cpp"
        [10] VMThread::loop(this = ???) (optimized), at 0xfe5b9cc4 (line ~423) in "vmThread.cpp"
        [11] VMThread::run(this = ???) (optimized), at 0xfe5b8fd4 (line ~227) in "vmThread.cpp"
        [12] java_start(thread_addr = ???) (optimized), at 0xfe2cc100 (line ~944) in "os_solaris.cpp"


      THREAD t@8

      This thread has called JVM/TI GetThreadListStackTraces() which is
      implemented by a VM operation. This thread is waiting for thread t@3
      (VMThread) to finish the VM operation.

      t@8 (l@8) stopped in ___lwp_cond_wait at 0xff29fa08
      0xff29fa08: ___lwp_cond_wait+0x0004: ta 8
      current thread: t@8
        [1] ___lwp_cond_wait(0xa68b8, 0xa68a0, 0x0, 0x7d0, 0xff098ab8, 0x7f97f4), at 0xff29fa08
        [2] _lwp_cond_wait(0xa68b8, 0xa68a0, 0xad318, 0x1, 0x0, 0x64400), at 0xff296f4c
      =>[3] Monitor::wait(this = ???, no_safepoint_check = ???, timeout = ???) (optimized), at 0xfe27c6c4 (line ~337) in "os_solaris.hpp"
        [4] VMThread::execute(op = ???) (optimized), at 0xfe5ba778 (line ~562) in "vmThread.cpp"
        [5] JvmtiEnv::GetThreadListStackTraces(this = ???, thread_count = ???, thread_list = ???, max_frame_count = ???, stack_info_ptr = ???) (optimized), at 0xfe0e19d8 (line ~829) in "jvmtiEnv.cpp"
        [6] jvmti_GetThreadListStackTraces(env = ???, thread_count = ???, thread_list = ???, max_frame_count = ???, stack_info_ptr = ???) (optimized), at 0xfdf86470 (line ~1206) in "jvmtiEnter.cpp"
        [7] getThreadListStackTraces(0xff08cca0, 0xfd6cc5e0, 0xfd6cc94c, 0x834, 0x800, 0x1539c), at 0xfd6b6dbc
        [8] trace_get_all_current(0x1, 0x2e238, 0x2e250, 0x4, 0x0, 0x2de30), at 0xfd6b1734
        [9] trace_increment_all_sample_costs(0x1, 0x2e238, 0x2e250, 0x4, 0x0, 0x2de30), at 0xfd6b18e4
        [10] tls_sample_all_threads(0x197104, 0xfd6cc5e0, 0x834, 0xfd6cc118, 0xfd6cc94c, 0x2e250), at 0xfd6afd50
        [11] cpu_loop_function(0xfd6cc5e0, 0x197104, 0xfd6b8204, 0xfd6b81ec, 0xfd6cc118, 0x1), at 0xfd6968e0
        [12] JvmtiAgentThread::call_start_function(this = ???) (optimized), at 0xfe14846c (line ~63) in "jvmtiImpl.cpp"
        [13] JavaThread::thread_main_inner(this = ???) (optimized), at 0xfe468080 (line ~1412) in "thread.cpp"
        [14] java_start(thread_addr = ???) (optimized), at 0xfe2cc100 (line ~944) in "os_solaris.cpp"

            rfield Robert Field (Inactive)
            dcubed Daniel Daugherty
            Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

              Created:
              Updated:
              Resolved:
              Imported:
              Indexed: