commit 70a596d61f8cf5b6447326c46c3386e0fbd5bfb5
author Mathieu Chartier <mathieuc@google.com> Wed Dec 17 14:56:47 2014 -0800
committer Mathieu Chartier <mathieuc@google.com> Wed Dec 17 16:03:58 2014 -0800
tree f7affe0a976165eb9ff789270d314463f6e36660
parent e9231c0aecc013c61b6cf7f88a228204651d4d41

Add thread suspend histogram

Helps measure time to suspend.
Example output (maps after a few seconds):
suspend all histogram:  Sum: 2.806ms 99% C.I. 2us-1090.560us Avg: 43.843us Max: 1126us

Change-Id: I7bd9dd3b401fb3e3059e8718556d60910e541611

runtime/thread_list.cc

diff --git a/runtime/thread_list.cc b/runtime/thread_list.cc
index 65a8bd0..968e89d 100644
--- a/runtime/thread_list.cc
+++ b/runtime/thread_list.cc
@@ -27,6 +27,7 @@
 
 #include <sstream>
 
+#include "base/histogram-inl.h"
 #include "base/mutex.h"
 #include "base/mutex-inl.h"
 #include "base/timing_logger.h"
@@ -46,7 +47,8 @@
 
 ThreadList::ThreadList()
     : suspend_all_count_(0), debug_suspend_all_count_(0),
-      thread_exit_cond_("thread exit condition variable", *Locks::thread_list_lock_) {
+      thread_exit_cond_("thread exit condition variable", *Locks::thread_list_lock_),
+      suspend_all_historam_("suspend all histogram", 16, 64) {
   CHECK(Monitor::IsValidLockWord(LockWord::FromThinLockId(kMaxThreadId, 1)));
 }
 
@@ -97,6 +99,12 @@
 }
 
 void ThreadList::DumpForSigQuit(std::ostream& os) {
+  {
+    ScopedObjectAccess soa(Thread::Current());
+    Histogram<uint64_t>::CumulativeData data;
+    suspend_all_historam_.CreateHistogram(&data);
+    suspend_all_historam_.PrintConfidenceIntervals(os, 0.99, data);  // Dump time to suspend.
+  }
   Dump(os);
   DumpUnattachedThreads(os);
 }
@@ -351,7 +359,7 @@
     VLOG(threads) << "Thread[null] SuspendAll starting...";
   }
   ATRACE_BEGIN("Suspending mutator threads");
-  uint64_t start_time = NanoTime();
+  const uint64_t start_time = NanoTime();
 
   Locks::mutator_lock_->AssertNotHeld(self);
   Locks::thread_list_lock_->AssertNotHeld(self);
@@ -384,9 +392,11 @@
   Locks::mutator_lock_->ExclusiveLock(self);
 #endif
 
-  uint64_t end_time = NanoTime();
-  if (end_time - start_time > kLongThreadSuspendThreshold) {
-    LOG(WARNING) << "Suspending all threads took: " << PrettyDuration(end_time - start_time);
+  const uint64_t end_time = NanoTime();
+  const uint64_t suspend_time = end_time - start_time;
+  suspend_all_historam_.AdjustAndAddValue(suspend_time);
+  if (suspend_time > kLongThreadSuspendThreshold) {
+    LOG(WARNING) << "Suspending all threads took: " << PrettyDuration(suspend_time);
   }
 
   if (kDebugLocking) {