Support for contention logging with ART futexes.

Remove dangerous postfix operators on AtomicInteger. Clean up the atomic stack.
Factor nanosleep into a useful shared utils.h routine.

Change-Id: I417a73007c23fe247f410f41b2fa41a717c22139

9 files changed, 246 insertions, 53 deletions

diff --git a/src/atomic_integer.h b/src/atomic_integer.h
index 0e07d2d94f..188f4c28b0 100644
--- a/src/atomic_integer.h
+++ b/src/atomic_integer.h
@@ -24,8 +24,7 @@ namespace art {
 
 class AtomicInteger {
  public:
-  // Default to uninitialized
-  AtomicInteger() { }
+  AtomicInteger() : value_(0) { }
 
   AtomicInteger(int32_t value) : value_(value) { }
 
@@ -59,14 +58,6 @@ class AtomicInteger {
     return android_atomic_and(-value, &value_);
   }
 
-  int32_t operator ++ (int32_t) {
-    return android_atomic_inc(&value_);
-  }
-
-  int32_t operator -- (int32_t) {
-    return android_atomic_dec(&value_);
-  }
-
   int32_t operator ++ () {
     return android_atomic_inc(&value_) + 1;
   }
@@ -75,8 +66,9 @@ class AtomicInteger {
     return android_atomic_dec(&value_) - 1;
   }
 
-  int CompareAndSwap(int expected_value, int new_value) {
-    return android_atomic_cas(expected_value, new_value, &value_);
+  bool CompareAndSwap(int expected_value, int new_value) {
+    bool success = android_atomic_cas(expected_value, new_value, &value_) == 0;
+    return success;
   }
  private:
   int32_t value_;
diff --git a/src/base/mutex.cc b/src/base/mutex.cc
index a5d890abc0..e2ab51f2f9 100644
--- a/src/base/mutex.cc
+++ b/src/base/mutex.cc
@@ -110,7 +110,60 @@ static bool ComputeRelativeTimeSpec(timespec* result_ts, const timespec& lhs, co
 }
 #endif
 
-BaseMutex::BaseMutex(const char* name, LockLevel level) : level_(level), name_(name) {}
+#if CONTENTION_LOGGING
+// A guard for all_mutexes_ that's not a mutex (Mutexes must CAS to acquire and busy wait).
+static AtomicInteger all_mutexes_guard_;
+// All created mutexes guarded by all_mutexes_guard_.
+std::set<BaseMutex*>* all_mutexes_;
+
+class ScopedAllMutexesLock {
+ public:
+  ScopedAllMutexesLock(const BaseMutex* mutex) : mutex_(mutex) {
+    while (!all_mutexes_guard_.CompareAndSwap(0, reinterpret_cast<int32_t>(mutex))) {
+      NanoSleep(100);
+    }
+  }
+  ~ScopedAllMutexesLock() {
+    while (!all_mutexes_guard_.CompareAndSwap(reinterpret_cast<int32_t>(mutex_), 0)) {
+      NanoSleep(100);
+    }
+  }
+ private:
+  const BaseMutex* const mutex_;
+};
+#endif
+
+BaseMutex::BaseMutex(const char* name, LockLevel level) : level_(level), name_(name) {
+#if CONTENTION_LOGGING
+  ScopedAllMutexesLock mu(this);
+  if (all_mutexes_ == NULL) {
+    // We leak the global set of all mutexes to avoid ordering issues in global variable
+    // construction/destruction.
+    all_mutexes_ = new std::set<BaseMutex*>();
+  }
+  all_mutexes_->insert(this);
+#endif
+}
+
+BaseMutex::~BaseMutex() {
+#if CONTENTION_LOGGING
+  ScopedAllMutexesLock mu(this);
+  all_mutexes_->erase(this);
+#endif
+}
+
+void BaseMutex::DumpAll(std::ostream& os) {
+#if CONTENTION_LOGGING
+  os << "Mutex logging:\n";
+  ScopedAllMutexesLock mu(reinterpret_cast<const BaseMutex*>(-1));
+  typedef std::set<BaseMutex*>::const_iterator It;
+  for (It it = all_mutexes_->begin(); it != all_mutexes_->end(); ++it) {
+    BaseMutex* mutex = *it;
+    mutex->Dump(os);
+    os << "\n";
+  }
+#endif
+}
 
 static void CheckUnattachedThread(LockLevel level) NO_THREAD_SAFETY_ANALYSIS {
   // The check below enumerates the cases where we expect not to be able to sanity check locks
@@ -188,6 +241,104 @@ void BaseMutex::CheckSafeToWait(Thread* self) {
   }
 }
 
+void BaseMutex::RecordContention(uint64_t blocked_tid, uint64_t owner_tid, uint64_t milli_time_blocked) {
+#if CONTENTION_LOGGING
+  ++contention_count_;
+  wait_time_ += static_cast<uint32_t>(milli_time_blocked);  // May overflow.
+  // This code is intentionally racy as it is only used for diagnostics.
+  uint32_t slot = cur_content_log_entry_;
+  if (contention_log_[slot].blocked_tid == blocked_tid &&
+      contention_log_[slot].owner_tid == blocked_tid) {
+    ++contention_log_[slot].count;
+  } else {
+    uint32_t new_slot;
+    do {
+      slot = cur_content_log_entry_;
+      new_slot = (slot + 1) % kContentionLogSize;
+    } while(!cur_content_log_entry_.CompareAndSwap(slot, new_slot));
+    contention_log_[new_slot].blocked_tid = blocked_tid;
+    contention_log_[new_slot].owner_tid = owner_tid;
+    contention_log_[new_slot].count = 1;
+  }
+#endif
+}
+
+class ScopedContentionRecorder {
+ public:
+  ScopedContentionRecorder(BaseMutex* mutex, uint64_t blocked_tid, uint64_t owner_tid) :
+      mutex_(mutex), blocked_tid_(blocked_tid), owner_tid_(owner_tid),
+      start_milli_time_(MilliTime()) {
+  }
+
+  ~ScopedContentionRecorder() {
+    uint64_t end_milli_time = MilliTime();
+    mutex_->RecordContention(blocked_tid_, owner_tid_, end_milli_time - start_milli_time_);
+  }
+
+ private:
+  BaseMutex* const mutex_;
+  uint64_t blocked_tid_;
+  uint64_t owner_tid_;
+  const uint64_t start_milli_time_;
+};
+
+void BaseMutex::DumpContention(std::ostream& os) const {
+#if CONTENTION_LOGGING
+  uint32_t wait_time = wait_time_;
+  uint32_t contention_count = contention_count_;
+  if (contention_count == 0) {
+    os << "never contended";
+  } else {
+    os << "contended " << contention_count << " times, average wait of contender " << (wait_time / contention_count) << "ms";
+    SafeMap<uint64_t, size_t> most_common_blocker;
+    SafeMap<uint64_t, size_t> most_common_blocked;
+    typedef SafeMap<uint64_t, size_t>::const_iterator It;
+    for (size_t i = 0; i < kContentionLogSize; ++i) {
+      uint64_t blocked_tid = contention_log_[i].blocked_tid;
+      uint64_t owner_tid = contention_log_[i].owner_tid;
+      uint32_t count = contention_log_[i].count;
+      if (count > 0) {
+        It it = most_common_blocked.find(blocked_tid);
+        if (it != most_common_blocked.end()) {
+          most_common_blocked.Overwrite(blocked_tid, it->second + count);
+        } else {
+          most_common_blocked.Put(blocked_tid, count);
+        }
+        it = most_common_blocker.find(owner_tid);
+        if (it != most_common_blocker.end()) {
+          most_common_blocker.Overwrite(owner_tid, it->second + count);
+        } else {
+          most_common_blocker.Put(owner_tid, count);
+        }
+      }
+    }
+    uint64_t max_tid = 0;
+    size_t max_tid_count = 0;
+    for (It it = most_common_blocked.begin(); it != most_common_blocked.end(); ++it) {
+      if (it->second > max_tid_count) {
+        max_tid = it->first;
+        max_tid_count = it->second;
+      }
+    }
+    if (max_tid != 0) {
+      os << " sample shows most blocked tid=" << max_tid;
+    }
+    max_tid = 0;
+    max_tid_count = 0;
+    for (It it = most_common_blocker.begin(); it != most_common_blocker.end(); ++it) {
+      if (it->second > max_tid_count) {
+        max_tid = it->first;
+        max_tid_count = it->second;
+      }
+    }
+    if (max_tid != 0) {
+      os << " sample shows tid=" << max_tid << " owning during this time";
+    }
+  }
+#endif
+}
+
+
 Mutex::Mutex(const char* name, LockLevel level, bool recursive)
     : BaseMutex(name, level), recursive_(recursive), recursion_count_(0) {
 #if ART_USE_FUTEXES
@@ -248,6 +399,7 @@ void Mutex::ExclusiveLock(Thread* self) {
         done = android_atomic_cmpxchg(0, 1, &state_) == 0;
       } else {
         // Failed to acquire, hang up.
+        ScopedContentionRecorder scr(this, GetExclusiveOwnerTid(), SafeGetTid(self));
         android_atomic_inc(&num_contenders_);
         if (futex(&state_, FUTEX_WAIT, 1, NULL, NULL, 0) != 0) {
           if (errno != EAGAIN) {
@@ -382,17 +534,18 @@ uint64_t Mutex::GetExclusiveOwnerTid() const {
 #endif
 }
 
-std::string Mutex::Dump() const {
-  return StringPrintf("%s %s level=%d count=%d owner=%llx",
-                      recursive_ ? "recursive" : "non-recursive",
-                      name_.c_str(),
-                      static_cast<int>(level_),
-                      recursion_count_,
-                      GetExclusiveOwnerTid());
+void Mutex::Dump(std::ostream& os) const {
+  os << (recursive_ ? "recursive " : "non-recursive ")
+      << name_
+      << " level=" << static_cast<int>(level_)
+      << " rec=" << recursion_count_
+      << " owner=" << GetExclusiveOwnerTid() << " ";
+  DumpContention(os);
 }
 
 std::ostream& operator<<(std::ostream& os, const Mutex& mu) {
-  return os << mu.Dump();
+  mu.Dump(os);
+  return os;
 }
 
 ReaderWriterMutex::ReaderWriterMutex(const char* name, LockLevel level) :
@@ -439,6 +592,7 @@ void ReaderWriterMutex::ExclusiveLock(Thread* self) {
       done = android_atomic_cmpxchg(0, -1, &state_) == 0;
     } else {
       // Failed to acquire, hang up.
+      ScopedContentionRecorder scr(this, GetExclusiveOwnerTid(), SafeGetTid(self));
       android_atomic_inc(&num_pending_writers_);
       if (futex(&state_, FUTEX_WAIT, cur_state, NULL, NULL, 0) != 0) {
         if (errno != EAGAIN) {
@@ -505,6 +659,7 @@ bool ReaderWriterMutex::ExclusiveLockWithTimeout(Thread* self, int64_t ms, int32
       if (ComputeRelativeTimeSpec(&rel_ts, end_abs_ts, now_abs_ts)) {
         return false;  // Timed out.
       }
+      ScopedContentionRecorder scr(this, GetExclusiveOwnerTid(), SafeGetTid(self));
       android_atomic_inc(&num_pending_writers_);
       if (futex(&state_, FUTEX_WAIT, cur_state, &rel_ts, NULL, 0) != 0) {
         if (errno == ETIMEDOUT) {
@@ -547,6 +702,7 @@ void ReaderWriterMutex::SharedLock(Thread* self) {
       done = android_atomic_cmpxchg(cur_state, cur_state + 1, &state_) == 0;
     } else {
       // Owner holds it exclusively, hang up.
+      ScopedContentionRecorder scr(this, GetExclusiveOwnerTid(), SafeGetTid(self));
       android_atomic_inc(&num_pending_readers_);
       if (futex(&state_, FUTEX_WAIT, cur_state, NULL, NULL, 0) != 0) {
         if (errno != EAGAIN) {
@@ -643,7 +799,14 @@ bool ReaderWriterMutex::IsSharedHeld(const Thread* self) const {
 
 uint64_t ReaderWriterMutex::GetExclusiveOwnerTid() const {
 #if ART_USE_FUTEXES
-  return exclusive_owner_;
+  int32_t state = state_;
+  if (state == 0) {
+    return 0;  // No owner.
+  } else if (state > 0) {
+    return -1;  // Shared.
+  } else {
+    return exclusive_owner_;
+  }
 #else
 #if defined(__BIONIC__)
   return rwlock_.writerThreadId;
@@ -665,15 +828,16 @@ uint64_t ReaderWriterMutex::GetExclusiveOwnerTid() const {
 #endif
 }
 
-std::string ReaderWriterMutex::Dump() const {
-  return StringPrintf("%s level=%d owner=%llx",
-                      name_.c_str(),
-                      static_cast<int>(level_),
-                      GetExclusiveOwnerTid());
+void ReaderWriterMutex::Dump(std::ostream& os) const {
+  os << name_
+      << " level=" << static_cast<int>(level_)
+      << " owner=" << GetExclusiveOwnerTid() << " ";
+  DumpContention(os);
 }
 
 std::ostream& operator<<(std::ostream& os, const ReaderWriterMutex& mu) {
-  return os << mu.Dump();
+  mu.Dump(os);
+  return os;
 }
 
 ConditionVariable::ConditionVariable(const std::string& name, Mutex& guard)
diff --git a/src/base/mutex.h b/src/base/mutex.h
index 190e7798ec..8576c03eee 100644
--- a/src/base/mutex.h
+++ b/src/base/mutex.h
@@ -41,8 +41,16 @@
 #define HAVE_TIMED_RWLOCK 0
 #endif
 
+// Record Log contention information, dumpable via SIGQUIT.
+#define CONTENTION_LOGGING (0 && ART_USE_FUTEXES)
+const size_t kContentionLogSize = 64;
+#if CONTENTION_LOGGING
+#include "atomic_integer.h"
+#endif
+
 namespace art {
 
+class ScopedContentionRecorder;
 class Thread;
 
 const bool kDebugLocking = kIsDebugBuild;
@@ -57,17 +65,43 @@ class BaseMutex {
   virtual bool IsMutex() const { return false; }
   virtual bool IsReaderWriterMutex() const { return false; }
 
+  virtual void Dump(std::ostream& os) const = 0;
+
+  static void DumpAll(std::ostream& os);
+
  protected:
   friend class ConditionVariable;
 
   BaseMutex(const char* name, LockLevel level);
-  virtual ~BaseMutex() {}
+  virtual ~BaseMutex();
   void RegisterAsLocked(Thread* self);
   void RegisterAsUnlocked(Thread* self);
   void CheckSafeToWait(Thread* self);
 
+  friend class ScopedContentionRecorder;
+
+  void RecordContention(uint64_t blocked_tid, uint64_t owner_tid, uint64_t milli_time_blocked);
+  void DumpContention(std::ostream& os) const;
+
   const LockLevel level_;  // Support for lock hierarchy.
   const std::string name_;
+#if CONTENTION_LOGGING
+  // A log entry that records contention but makes no guarantee that either tid will be held live.
+  struct ContentionLogEntry {
+    ContentionLogEntry() : blocked_tid(0), owner_tid(0) {}
+    uint64_t blocked_tid;
+    uint64_t owner_tid;
+    AtomicInteger count;
+  };
+  ContentionLogEntry contention_log_[kContentionLogSize];
+  // The next entry in the contention log to be updated. Value ranges from 0 to
+  // kContentionLogSize - 1.
+  AtomicInteger cur_content_log_entry_;
+  // Number of times the Mutex has been contended.
+  AtomicInteger contention_count_;
+  // Sum of time waited by all contenders in ms.
+  AtomicInteger wait_time_;
+#endif
 };
 
 // A Mutex is used to achieve mutual exclusion between threads. A Mutex can be used to gain
@@ -129,7 +163,7 @@ class LOCKABLE Mutex : public BaseMutex {
     return recursion_count_;
   }
 
-  std::string Dump() const;
+  virtual void Dump(std::ostream& os) const;
 
  private:
 #if ART_USE_FUTEXES
@@ -240,7 +274,7 @@ class LOCKABLE ReaderWriterMutex : public BaseMutex {
   // Id associated with exclusive owner.
   uint64_t GetExclusiveOwnerTid() const;
 
-  std::string Dump() const;
+  virtual void Dump(std::ostream& os) const;
 
  private:
 #if ART_USE_FUTEXES
diff --git a/src/compiler.cc b/src/compiler.cc
index aa2ec4012a..ff8b75649d 100644
--- a/src/compiler.cc
+++ b/src/compiler.cc
@@ -481,12 +481,12 @@ void Compiler::CompileAll(jobject class_loader,
                           const std::vector<const DexFile*>& dex_files) {
   DCHECK(!Runtime::Current()->IsStarted());
 
-  ThreadPool thread_pool(thread_count_);
+  UniquePtr<ThreadPool> thread_pool(new ThreadPool(thread_count_));
   TimingLogger timings("compiler");
 
-  PreCompile(class_loader, dex_files, thread_pool, timings);
+  PreCompile(class_loader, dex_files, *thread_pool.get(), timings);
 
-  Compile(class_loader, dex_files, thread_pool, timings);
+  Compile(class_loader, dex_files, *thread_pool.get(), timings);
 
   if (dump_timings_ && timings.GetTotalNs() > MsToNs(1000)) {
     timings.Dump();
@@ -519,9 +519,9 @@ void Compiler::CompileOne(const AbstractMethod* method) {
   std::vector<const DexFile*> dex_files;
   dex_files.push_back(dex_file);
 
-  ThreadPool thread_pool(1U);
+  UniquePtr<ThreadPool> thread_pool(new ThreadPool(1U));
   TimingLogger timings("CompileOne");
-  PreCompile(class_loader, dex_files, thread_pool, timings);
+  PreCompile(class_loader, dex_files, *thread_pool.get(), timings);
 
   uint32_t method_idx = method->GetDexMethodIndex();
   const DexFile::CodeItem* code_item = dex_file->GetCodeItem(method->GetCodeItemOffset());
diff --git a/src/gc/atomic_stack.h b/src/gc/atomic_stack.h
index 8de5e359cf..cd1781dcb9 100644
--- a/src/gc/atomic_stack.h
+++ b/src/gc/atomic_stack.h
@@ -57,12 +57,14 @@ class AtomicStack {
 
   // Returns false if we overflowed the stack.
   bool AtomicPushBack(const T& value) {
-    const int32_t index = back_index_++;
-    if (UNLIKELY(static_cast<size_t>(index) >= capacity_)) {
-      // Stack overflow.
-      back_index_--;
-      return false;
-    }
+    int32_t index;
+    do {
+      index = back_index_;
+      if (UNLIKELY(static_cast<size_t>(index) >= capacity_)) {
+        // Stack overflow.
+        return false;
+      }
+    } while(!back_index_.CompareAndSwap(index, index + 1));
     begin_[index] = value;
     return true;
   }
@@ -81,13 +83,6 @@ class AtomicStack {
     return begin_[back_index_];
   }
 
-  T AtomicPopBack() {
-    // Decrement the back index non atomically.
-    int back_index = back_index_--;
-    DCHECK_GT(back_index, front_index_);
-    return begin_[back_index - 1];
-  }
-
   // Take an item from the front of the stack.
   T PopFront() {
     int32_t index = front_index_;
diff --git a/src/monitor.cc b/src/monitor.cc
index 6673d198c2..47c87cb259 100644
--- a/src/monitor.cc
+++ b/src/monitor.cc
@@ -585,7 +585,6 @@ void Monitor::Inflate(Thread* self, Object* obj) {
 
 void Monitor::MonitorEnter(Thread* self, Object* obj) {
   volatile int32_t* thinp = obj->GetRawLockWordAddress();
-  timespec tm;
   uint32_t sleepDelayNs;
   uint32_t minSleepDelayNs = 1000000;  /* 1 millisecond */
   uint32_t maxSleepDelayNs = 1000000000;  /* 1 second */
@@ -651,9 +650,7 @@ void Monitor::MonitorEnter(Thread* self, Object* obj) {
               sched_yield();
               sleepDelayNs = minSleepDelayNs;
             } else {
-              tm.tv_sec = 0;
-              tm.tv_nsec = sleepDelayNs;
-              nanosleep(&tm, NULL);
+              NanoSleep(sleepDelayNs);
               // Prepare the next delay value. Wrap to avoid once a second polls for eternity.
               if (sleepDelayNs < maxSleepDelayNs / 2) {
                 sleepDelayNs *= 2;
diff --git a/src/runtime.cc b/src/runtime.cc
index 2416581415..4cf7d9793f 100644
--- a/src/runtime.cc
+++ b/src/runtime.cc
@@ -917,6 +917,7 @@ void Runtime::DumpForSigQuit(std::ostream& os) {
   os << "\n";
 
   thread_list_->DumpForSigQuit(os);
+  BaseMutex::DumpAll(os);
 }
 
 void Runtime::DumpLockHolders(std::ostream& os) {
diff --git a/src/utils.cc b/src/utils.cc
index 78d359921f..e2231c2154 100644
--- a/src/utils.cc
+++ b/src/utils.cc
@@ -180,6 +180,13 @@ uint64_t ThreadCpuNanoTime() {
 #endif
 }
 
+void NanoSleep(uint64_t ns) {
+  timespec tm;
+  tm.tv_sec = 0;
+  tm.tv_nsec = ns;
+  nanosleep(&tm, NULL);
+}
+
 void InitTimeSpec(bool absolute, int clock, int64_t ms, int32_t ns, timespec* ts) {
   int64_t endSec;
 
diff --git a/src/utils.h b/src/utils.h
index 40f07688b3..640743ccf8 100644
--- a/src/utils.h
+++ b/src/utils.h
@@ -291,6 +291,9 @@ static inline uint64_t MsToNs(uint64_t ns) {
 #define CLOCK_REALTIME 0xebadf00d
 #endif
 
+// Sleep for the given number of nanoseconds, a bad way to handle contention.
+void NanoSleep(uint64_t ns);
+
 // Initialize a timespec to either an absolute or relative time.
 void InitTimeSpec(bool absolute, int clock, int64_t ms, int32_t ns, timespec* ts);