# HG changeset patch # User dcubed # Date 1436891600 25200 # Node ID b23b74f8ae8df6ce705d27b191d235030b8b7777 # Parent 6bc2497120a9894360fa6a284a89f6673c391aed 8130448: thread dump improvements, comment additions, new diagnostics inspired by 8077392 Reviewed-by: dholmes, coleenp diff -r 6bc2497120a9 -r b23b74f8ae8d hotspot/src/cpu/x86/vm/macroAssembler_x86.cpp --- a/hotspot/src/cpu/x86/vm/macroAssembler_x86.cpp Tue Jul 14 11:40:49 2015 +0200 +++ b/hotspot/src/cpu/x86/vm/macroAssembler_x86.cpp Tue Jul 14 09:33:20 2015 -0700 @@ -1781,6 +1781,7 @@ cmpxchgptr(scrReg, Address(boxReg, OM_OFFSET_NO_MONITOR_VALUE_TAG(owner))); } else if ((EmitSync & 128) == 0) { // avoid ST-before-CAS + // register juggle because we need tmpReg for cmpxchgptr below movptr(scrReg, boxReg); movptr(boxReg, tmpReg); // consider: LEA box, [tmp-2] @@ -1814,7 +1815,10 @@ } cmpxchgptr(scrReg, Address(boxReg, OM_OFFSET_NO_MONITOR_VALUE_TAG(owner))); movptr(Address(scrReg, 0), 3); // box->_displaced_header = 3 + // If we weren't able to swing _owner from NULL to the BasicLock + // then take the slow path. jccb (Assembler::notZero, DONE_LABEL); + // update _owner from BasicLock to thread get_thread (scrReg); // beware: clobbers ICCs movptr(Address(boxReg, OM_OFFSET_NO_MONITOR_VALUE_TAG(owner)), scrReg); xorptr(boxReg, boxReg); // set icc.ZFlag = 1 to indicate success @@ -2083,6 +2087,9 @@ xorptr(boxReg, boxReg); // box is really EAX if (os::is_MP()) { lock(); } cmpxchgptr(rsp, Address(tmpReg, OM_OFFSET_NO_MONITOR_VALUE_TAG(owner))); + // There's no successor so we tried to regrab the lock with the + // placeholder value. If that didn't work, then another thread + // grabbed the lock so we're done (and exit was a success). jccb (Assembler::notEqual, LSuccess); // Since we're low on registers we installed rsp as a placeholding in _owner. // Now install Self over rsp. This is safe as we're transitioning from @@ -2190,6 +2197,9 @@ movptr(boxReg, (int32_t)NULL_WORD); if (os::is_MP()) { lock(); } cmpxchgptr(r15_thread, Address(tmpReg, OM_OFFSET_NO_MONITOR_VALUE_TAG(owner))); + // There's no successor so we tried to regrab the lock. + // If that didn't work, then another thread grabbed the + // lock so we're done (and exit was a success). jccb (Assembler::notEqual, LSuccess); // Intentional fall-through into slow-path diff -r 6bc2497120a9 -r b23b74f8ae8d hotspot/src/share/vm/oops/markOop.cpp --- a/hotspot/src/share/vm/oops/markOop.cpp Tue Jul 14 11:40:49 2015 +0200 +++ b/hotspot/src/share/vm/oops/markOop.cpp Tue Jul 14 09:33:20 2015 -0700 @@ -32,26 +32,32 @@ void markOopDesc::print_on(outputStream* st) const { if (is_marked()) { st->print(" marked(" INTPTR_FORMAT ")", value()); + } else if (has_monitor()) { + // have to check has_monitor() before is_locked() + st->print(" monitor(" INTPTR_FORMAT ")=", value()); + ObjectMonitor* mon = monitor(); + if (mon == NULL) { + st->print("NULL (this should never be seen!)"); + } else { + st->print("{count=" INTPTR_FORMAT ",waiters=" INTPTR_FORMAT + ",recursions=" INTPTR_FORMAT ",owner=" INTPTR_FORMAT "}", + mon->count(), mon->waiters(), mon->recursions(), + p2i(mon->owner())); + } } else if (is_locked()) { st->print(" locked(" INTPTR_FORMAT ")->", value()); if (is_neutral()) { st->print("is_neutral"); - if (has_no_hash()) st->print(" no_hash"); - else st->print(" hash=" INTPTR_FORMAT, hash()); + if (has_no_hash()) { + st->print(" no_hash"); + } else { + st->print(" hash=" INTPTR_FORMAT, hash()); + } st->print(" age=%d", age()); } else if (has_bias_pattern()) { st->print("is_biased"); JavaThread* jt = biased_locker(); st->print(" biased_locker=" INTPTR_FORMAT, p2i(jt)); - } else if (has_monitor()) { - ObjectMonitor* mon = monitor(); - if (mon == NULL) - st->print("monitor=NULL"); - else { - BasicLock * bl = (BasicLock *) mon->owner(); - st->print("monitor={count=" INTPTR_FORMAT ",waiters=" INTPTR_FORMAT ",recursions=" INTPTR_FORMAT ",owner=" INTPTR_FORMAT "}", - mon->count(), mon->waiters(), mon->recursions(), p2i(bl)); - } } else { st->print("??"); } diff -r 6bc2497120a9 -r b23b74f8ae8d hotspot/src/share/vm/runtime/objectMonitor.cpp --- a/hotspot/src/share/vm/runtime/objectMonitor.cpp Tue Jul 14 11:40:49 2015 +0200 +++ b/hotspot/src/share/vm/runtime/objectMonitor.cpp Tue Jul 14 09:33:20 2015 -0700 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1998, 2014, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1998, 2015, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -103,8 +103,10 @@ // The knob* variables are effectively final. Once set they should // never be modified hence. Consider using __read_mostly with GCC. +int ObjectMonitor::Knob_ExitRelease = 0; int ObjectMonitor::Knob_Verbose = 0; int ObjectMonitor::Knob_VerifyInUse = 0; +int ObjectMonitor::Knob_VerifyMatch = 0; int ObjectMonitor::Knob_SpinLimit = 5000; // derived by an external tool - static int Knob_LogSpins = 0; // enable jvmstat tally for spins static int Knob_HandOff = 0; @@ -251,24 +253,6 @@ // ----------------------------------------------------------------------------- // Enter support -bool ObjectMonitor::try_enter(Thread* THREAD) { - if (THREAD != _owner) { - if (THREAD->is_lock_owned ((address)_owner)) { - assert(_recursions == 0, "internal state error"); - _owner = THREAD; - _recursions = 1; - return true; - } - if (Atomic::cmpxchg_ptr (THREAD, &_owner, NULL) != NULL) { - return false; - } - return true; - } else { - _recursions++; - return true; - } -} - void NOINLINE ObjectMonitor::enter(TRAPS) { // The following code is ordered to check the most common cases first // and to reduce RTS->RTO cache line upgrades on SPARC and IA32 processors. @@ -2272,7 +2256,7 @@ } inline void ObjectMonitor::AddWaiter(ObjectWaiter* node) { - assert(node != NULL, "should not dequeue NULL node"); + assert(node != NULL, "should not add NULL node"); assert(node->_prev == NULL, "node already in list"); assert(node->_next == NULL, "node already in list"); // put node at end of queue (circular doubly linked list) @@ -2407,8 +2391,8 @@ char * v = kvGet(kvList, Key); int rslt = v ? ::strtol(v, NULL, 0) : Default; if (Knob_ReportSettings && v != NULL) { - ::printf (" SyncKnob: %s %d(%d)\n", Key, rslt, Default) ; - ::fflush(stdout); + tty->print_cr("INFO: SyncKnob: %s %d(%d)", Key, rslt, Default) ; + tty->flush(); } return rslt; } @@ -2442,8 +2426,10 @@ #define SETKNOB(x) { Knob_##x = kvGetInt(knobs, #x, Knob_##x); } SETKNOB(ReportSettings); + SETKNOB(ExitRelease); SETKNOB(Verbose); SETKNOB(VerifyInUse); + SETKNOB(VerifyMatch); SETKNOB(FixedSpin); SETKNOB(SpinLimit); SETKNOB(SpinBase); @@ -2477,7 +2463,9 @@ if (os::is_MP()) { BackOffMask = (1 << Knob_SpinBackOff) - 1; - if (Knob_ReportSettings) ::printf("BackOffMask=%X\n", BackOffMask); + if (Knob_ReportSettings) { + tty->print_cr("INFO: BackOffMask=0x%X", BackOffMask); + } // CONSIDER: BackOffMask = ROUNDUP_NEXT_POWER2 (ncpus-1) } else { Knob_SpinLimit = 0; diff -r 6bc2497120a9 -r b23b74f8ae8d hotspot/src/share/vm/runtime/objectMonitor.hpp --- a/hotspot/src/share/vm/runtime/objectMonitor.hpp Tue Jul 14 11:40:49 2015 +0200 +++ b/hotspot/src/share/vm/runtime/objectMonitor.hpp Tue Jul 14 09:33:20 2015 -0700 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1998, 2014, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1998, 2015, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -196,8 +196,10 @@ static PerfCounter * _sync_Deflations; static PerfLongVariable * _sync_MonExtant; + static int Knob_ExitRelease; static int Knob_Verbose; static int Knob_VerifyInUse; + static int Knob_VerifyMatch; static int Knob_SpinLimit; void* operator new (size_t size) throw() { @@ -317,7 +319,6 @@ void print(); #endif - bool try_enter(TRAPS); void enter(TRAPS); void exit(bool not_suspended, TRAPS); void wait(jlong millis, bool interruptable, TRAPS); @@ -354,14 +355,14 @@ #undef TEVENT #define TEVENT(nom) { if (SyncVerbose) FEVENT(nom); } -#define FEVENT(nom) \ - { \ - static volatile int ctr = 0; \ - int v = ++ctr; \ - if ((v & (v - 1)) == 0) { \ - ::printf(#nom " : %d\n", v); \ - ::fflush(stdout); \ - } \ +#define FEVENT(nom) \ + { \ + static volatile int ctr = 0; \ + int v = ++ctr; \ + if ((v & (v - 1)) == 0) { \ + tty->print_cr("INFO: " #nom " : %d", v); \ + tty->flush(); \ + } \ } #undef TEVENT diff -r 6bc2497120a9 -r b23b74f8ae8d hotspot/src/share/vm/runtime/synchronizer.cpp --- a/hotspot/src/share/vm/runtime/synchronizer.cpp Tue Jul 14 11:40:49 2015 +0200 +++ b/hotspot/src/share/vm/runtime/synchronizer.cpp Tue Jul 14 09:33:20 2015 -0700 @@ -40,6 +40,7 @@ #include "runtime/stubRoutines.hpp" #include "runtime/synchronizer.hpp" #include "runtime/thread.inline.hpp" +#include "runtime/vframe.hpp" #include "utilities/dtrace.hpp" #include "utilities/events.hpp" #include "utilities/preserveException.hpp" @@ -927,8 +928,9 @@ if (ForceMonitorScavenge == 0 && Atomic::xchg (1, &ForceMonitorScavenge) == 0) { if (ObjectMonitor::Knob_Verbose) { - ::printf ("Monitor scavenge - Induced STW @%s (%d)\n", Whence, ForceMonitorScavenge) ; - ::fflush(stdout); + tty->print_cr("INFO: Monitor scavenge - Induced STW @%s (%d)", + Whence, ForceMonitorScavenge) ; + tty->flush(); } // Induce a 'null' safepoint to scavenge monitors // Must VM_Operation instance be heap allocated as the op will be enqueue and posted @@ -937,8 +939,9 @@ VMThread::execute(new VM_ForceAsyncSafepoint()); if (ObjectMonitor::Knob_Verbose) { - ::printf ("Monitor scavenge - STW posted @%s (%d)\n", Whence, ForceMonitorScavenge) ; - ::fflush(stdout); + tty->print_cr("INFO: Monitor scavenge - STW posted @%s (%d)", + Whence, ForceMonitorScavenge) ; + tty->flush(); } } } @@ -1603,10 +1606,11 @@ // Consider: audit gFreeList to ensure that gMonitorFreeCount and list agree. if (ObjectMonitor::Knob_Verbose) { - ::printf("Deflate: InCirc=%d InUse=%d Scavenged=%d ForceMonitorScavenge=%d : pop=%d free=%d\n", - nInCirculation, nInuse, nScavenged, ForceMonitorScavenge, - gMonitorPopulation, gMonitorFreeCount); - ::fflush(stdout); + tty->print_cr("INFO: Deflate: InCirc=%d InUse=%d Scavenged=%d " + "ForceMonitorScavenge=%d : pop=%d free=%d", + nInCirculation, nInuse, nScavenged, ForceMonitorScavenge, + gMonitorPopulation, gMonitorFreeCount); + tty->flush(); } ForceMonitorScavenge = 0; // Reset @@ -1643,6 +1647,14 @@ ReleaseJavaMonitorsClosure(Thread* thread) : THREAD(thread) {} void do_monitor(ObjectMonitor* mid) { if (mid->owner() == THREAD) { + if (ObjectMonitor::Knob_VerifyMatch != 0) { + Handle obj((oop) mid->object()); + tty->print("INFO: unexpected locked object:"); + javaVFrame::print_locked_object_class_name(tty, obj, "locked"); + fatal(err_msg("exiting JavaThread=" INTPTR_FORMAT + " unexpectedly owns ObjectMonitor=" INTPTR_FORMAT, + THREAD, mid)); + } (void)mid->complete_exit(CHECK); } } diff -r 6bc2497120a9 -r b23b74f8ae8d hotspot/src/share/vm/runtime/thread.cpp --- a/hotspot/src/share/vm/runtime/thread.cpp Tue Jul 14 11:40:49 2015 +0200 +++ b/hotspot/src/share/vm/runtime/thread.cpp Tue Jul 14 09:33:20 2015 -0700 @@ -1802,14 +1802,25 @@ assert(!this->has_pending_exception(), "ensure_join should have cleared"); // 6282335 JNI DetachCurrentThread spec states that all Java monitors - // held by this thread must be released. A detach operation must only - // get here if there are no Java frames on the stack. Therefore, any - // owned monitors at this point MUST be JNI-acquired monitors which are - // pre-inflated and in the monitor cache. + // held by this thread must be released. The spec does not distinguish + // between JNI-acquired and regular Java monitors. We can only see + // regular Java monitors here if monitor enter-exit matching is broken. + // + // Optionally release any monitors for regular JavaThread exits. This + // is provided as a work around for any bugs in monitor enter-exit + // matching. This can be expensive so it is not enabled by default. + // ObjectMonitor::Knob_ExitRelease is a superset of the + // JNIDetachReleasesMonitors option. // - // ensure_join() ignores IllegalThreadStateExceptions, and so does this. - if (exit_type == jni_detach && JNIDetachReleasesMonitors) { - assert(!this->has_last_Java_frame(), "detaching with Java frames?"); + // ensure_join() ignores IllegalThreadStateExceptions, and so does + // ObjectSynchronizer::release_monitors_owned_by_thread(). + if ((exit_type == jni_detach && JNIDetachReleasesMonitors) || + ObjectMonitor::Knob_ExitRelease) { + // Sanity check even though JNI DetachCurrentThread() would have + // returned JNI_ERR if there was a Java frame. JavaThread exit + // should be done executing Java code by the time we get here. + assert(!this->has_last_Java_frame(), + "should not have a Java frame when detaching or exiting"); ObjectSynchronizer::release_monitors_owned_by_thread(this); assert(!this->has_pending_exception(), "release_monitors should have cleared"); } diff -r 6bc2497120a9 -r b23b74f8ae8d hotspot/src/share/vm/runtime/vframe.cpp --- a/hotspot/src/share/vm/runtime/vframe.cpp Tue Jul 14 11:40:49 2015 +0200 +++ b/hotspot/src/share/vm/runtime/vframe.cpp Tue Jul 14 09:33:20 2015 -0700 @@ -144,7 +144,7 @@ return result; } -static void print_locked_object_class_name(outputStream* st, Handle obj, const char* lock_state) { +void javaVFrame::print_locked_object_class_name(outputStream* st, Handle obj, const char* lock_state) { if (obj.not_null()) { st->print("\t- %s <" INTPTR_FORMAT "> ", lock_state, (address)obj()); if (obj->klass() == SystemDictionary::Class_klass()) { @@ -160,17 +160,29 @@ void javaVFrame::print_lock_info_on(outputStream* st, int frame_count) { ResourceMark rm; - // If this is the first frame, and java.lang.Object.wait(...) then print out the receiver. + // If this is the first frame and it is java.lang.Object.wait(...) + // then print out the receiver. Locals are not always available, + // e.g., compiled native frames have no scope so there are no locals. if (frame_count == 0) { if (method()->name() == vmSymbols::wait_name() && method()->method_holder()->name() == vmSymbols::java_lang_Object()) { + const char *wait_state = "waiting on"; // assume we are waiting + // If earlier in the output we reported java.lang.Thread.State == + // "WAITING (on object monitor)" and now we report "waiting on", then + // we are still waiting for notification or timeout. Otherwise if + // we earlier reported java.lang.Thread.State == "BLOCKED (on object + // monitor)", then we are actually waiting to re-lock the monitor. + // At this level we can't distinguish the two cases to report + // "waited on" rather than "waiting on" for the second case. StackValueCollection* locs = locals(); if (!locs->is_empty()) { StackValue* sv = locs->at(0); if (sv->type() == T_OBJECT) { Handle o = locs->at(0)->get_obj(); - print_locked_object_class_name(st, o, "waiting on"); + print_locked_object_class_name(st, o, wait_state); } + } else { + st->print_cr("\t- %s ", wait_state); } } else if (thread()->current_park_blocker() != NULL) { oop obj = thread()->current_park_blocker(); @@ -179,8 +191,8 @@ } } - - // Print out all monitors that we have locked or are trying to lock + // Print out all monitors that we have locked, or are trying to lock, + // including re-locking after being notified or timing out in a wait(). GrowableArray* mons = monitors(); if (!mons->is_empty()) { bool found_first_monitor = false; @@ -202,14 +214,14 @@ if (monitor->owner() != NULL) { // the monitor is associated with an object, i.e., it is locked - // First, assume we have the monitor locked. If we haven't found an - // owned monitor before and this is the first frame, then we need to - // see if we have completed the lock or we are blocked trying to - // acquire it - we can only be blocked if the monitor is inflated - markOop mark = NULL; const char *lock_state = "locked"; // assume we have the monitor locked if (!found_first_monitor && frame_count == 0) { + // If this is the first frame and we haven't found an owned + // monitor before, then we need to see if we have completed + // the lock or if we are blocked trying to acquire it. Only + // an inflated monitor that is first on the monitor list in + // the first frame can block us on a monitor enter. mark = monitor->owner()->mark(); if (mark->has_monitor() && ( // we have marked ourself as pending on this monitor @@ -219,13 +231,33 @@ )) { lock_state = "waiting to lock"; } else { - mark = NULL; // Disable printing below + // We own the monitor which is not as interesting so + // disable the extra printing below. + mark = NULL; + } + } else if (frame_count != 0) { + // This is not the first frame so we either own this monitor + // or we owned the monitor before and called wait(). Because + // wait() could have been called on any monitor in a lower + // numbered frame on the stack, we have to check all the + // monitors on the list for this frame. + mark = monitor->owner()->mark(); + if (mark->has_monitor() && + ( // we have marked ourself as pending on this monitor + mark->monitor() == thread()->current_pending_monitor() || + // we are not the owner of this monitor + !mark->monitor()->is_entered(thread()) + )) { + lock_state = "waiting to re-lock in wait()"; + } else { + // We own the monitor which is not as interesting so + // disable the extra printing below. + mark = NULL; } } print_locked_object_class_name(st, monitor->owner(), lock_state); - if (Verbose && mark != NULL) { - // match with format above, replacing "-" with " ". - st->print("\t lockbits="); + if (ObjectMonitor::Knob_Verbose && mark != NULL) { + st->print("\t- lockbits="); mark->print_on(st); st->cr(); } diff -r 6bc2497120a9 -r b23b74f8ae8d hotspot/src/share/vm/runtime/vframe.hpp --- a/hotspot/src/share/vm/runtime/vframe.hpp Tue Jul 14 11:40:49 2015 +0200 +++ b/hotspot/src/share/vm/runtime/vframe.hpp Tue Jul 14 09:33:20 2015 -0700 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2014, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2015, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -135,7 +135,8 @@ // Return an array of monitors locked by this frame in the youngest to oldest order GrowableArray* locked_monitors(); - // printing used during stack dumps + // printing used during stack dumps and diagnostics + static void print_locked_object_class_name(outputStream* st, Handle obj, const char* lock_state); void print_lock_info_on(outputStream* st, int frame_count); void print_lock_info(int frame_count) { print_lock_info_on(tty, frame_count); }