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

6 files changed, 29 insertions, 11 deletions

diff --git a/runtime/base/histogram-inl.h b/runtime/base/histogram-inl.h
index b329a31b1f..812ed86e40 100644
--- a/runtime/base/histogram-inl.h
+++ b/runtime/base/histogram-inl.h
@@ -35,10 +35,13 @@ template <class Value> inline void Histogram<Value>::AddValue(Value value) {
     DCHECK_GT(new_max, max_);
     GrowBuckets(new_max);
   }
-
   BucketiseValue(value);
 }
 
+template <class Value> inline void Histogram<Value>::AdjustAndAddValue(Value value) {
+  AddValue(value / kAdjust);
+}
+
 template <class Value> inline Histogram<Value>::Histogram(const char* name)
     : kAdjust(0),
       kInitialBucketCount(0),
diff --git a/runtime/base/histogram.h b/runtime/base/histogram.h
index 1e12be8c3e..78f6e1c7c7 100644
--- a/runtime/base/histogram.h
+++ b/runtime/base/histogram.h
@@ -46,6 +46,7 @@ template <class Value> class Histogram {
   // This is the expected constructor when creating new Histograms.
   Histogram(const char* name, Value initial_bucket_width, size_t max_buckets = 100);
   void AddValue(Value);
+  void AdjustAndAddValue(Value);  // Add a value after dividing it by kAdjust.
   // Builds the cumulative distribution function from the frequency data.
   // Accumulative summation of frequencies.
   // cumulative_freq[i] = sum(frequency[j] : 0 < j < i )
diff --git a/runtime/gc/collector/garbage_collector.cc b/runtime/gc/collector/garbage_collector.cc
index 9e6a8003f4..8be18be676 100644
--- a/runtime/gc/collector/garbage_collector.cc
+++ b/runtime/gc/collector/garbage_collector.cc
@@ -102,7 +102,7 @@ void GarbageCollector::Run(GcCause gc_cause, bool clear_soft_references) {
   total_time_ns_ += current_iteration->GetDurationNs();
   for (uint64_t pause_time : current_iteration->GetPauseTimes()) {
     MutexLock mu(self, pause_histogram_lock_);
-    pause_histogram_.AddValue(pause_time / 1000);
+    pause_histogram_.AdjustAndAddValue(pause_time);
   }
   ATRACE_END();
 }
diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc
index 0587bb5aba..d27e282776 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -859,7 +859,7 @@ void Heap::DumpGcPerformanceInfo(std::ostream& os) {
     os << "Zygote space size " << PrettySize(zygote_space_->Size()) << "\n";
   }
   os << "Total mutator paused time: " << PrettyDuration(total_paused_time) << "\n";
-  os << "Total time waiting for GC to complete: " << PrettyDuration(total_wait_time_) << "\n";
+  os << "Total time waiting for GC to complete: " << PrettyDuration(total_wait_time_);
   BaseMutex::DumpAll(os);
 }
 
diff --git a/runtime/thread_list.cc b/runtime/thread_list.cc
index 65a8bd04ad..968e89d1da 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 @@ static constexpr uint64_t kLongThreadSuspendThreshold = MsToNs(5);
 
 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::DumpNativeStacks(std::ostream& os) {
 }
 
 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 @@ void ThreadList::SuspendAll() {
     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 @@ void ThreadList::SuspendAll() {
   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) {
diff --git a/runtime/thread_list.h b/runtime/thread_list.h
index 13684c7668..43c065ae0a 100644
--- a/runtime/thread_list.h
+++ b/runtime/thread_list.h
@@ -17,6 +17,7 @@
 #ifndef ART_RUNTIME_THREAD_LIST_H_
 #define ART_RUNTIME_THREAD_LIST_H_
 
+#include "base/histogram.h"
 #include "base/mutex.h"
 #include "jni.h"
 #include "object_callbacks.h"
@@ -39,11 +40,10 @@ class ThreadList {
   ~ThreadList();
 
   void DumpForSigQuit(std::ostream& os)
-      LOCKS_EXCLUDED(Locks::thread_list_lock_);
+      LOCKS_EXCLUDED(Locks::thread_list_lock_, Locks::mutator_lock_);
   // For thread suspend timeout dumps.
   void Dump(std::ostream& os)
-      LOCKS_EXCLUDED(Locks::thread_list_lock_,
-                     Locks::thread_suspend_count_lock_);
+      LOCKS_EXCLUDED(Locks::thread_list_lock_, Locks::thread_suspend_count_lock_);
   pid_t GetLockOwner();  // For SignalCatcher.
 
   // Thread suspension support.
@@ -169,6 +169,10 @@ class ThreadList {
   // Signaled when threads terminate. Used to determine when all non-daemons have terminated.
   ConditionVariable thread_exit_cond_ GUARDED_BY(Locks::thread_list_lock_);
 
+  // Thread suspend time histogram. Only modified when all the threads are suspended, so guarding
+  // by mutator lock ensures no thread can read when another thread is modifying it.
+  Histogram<uint64_t> suspend_all_historam_ GUARDED_BY(Locks::mutator_lock_);
+
   friend class Thread;
 
   DISALLOW_COPY_AND_ASSIGN(ThreadList);