Add histogram for GC pause times.

Printed when you dump the GC performance info.

Bug: 10855285
Change-Id: I3bf7f958305f97c52cb31c03bdd6218c321575b9

7 files changed, 28 insertions, 20 deletions

diff --git a/runtime/base/histogram-inl.h b/runtime/base/histogram-inl.h
index 4cd68cd..7c09999 100644
--- a/runtime/base/histogram-inl.h
+++ b/runtime/base/histogram-inl.h
@@ -178,7 +178,8 @@ inline void Histogram<Value>::PrintConfidenceIntervals(std::ostream &os, double
   os << FormatDuration(Max() * kAdjust, unit) << "\n";
 }
 
-template <class Value> inline void Histogram<Value>::CreateHistogram(CumulativeData* out_data) {
+template <class Value>
+inline void Histogram<Value>::CreateHistogram(CumulativeData* out_data) const {
   DCHECK_GT(sample_size_, 0ull);
   out_data->freq_.clear();
   out_data->perc_.clear();
diff --git a/runtime/base/histogram.h b/runtime/base/histogram.h
index d4eb1f4..4e5d29a 100644
--- a/runtime/base/histogram.h
+++ b/runtime/base/histogram.h
@@ -49,7 +49,7 @@ template <class Value> class Histogram {
   // cumulative_freq[i] = sum(frequency[j] : 0 < j < i )
   // Accumulative summation of percentiles; which is the frequency / SampleSize
   // cumulative_perc[i] = sum(frequency[j] / SampleSize : 0 < j < i )
-  void CreateHistogram(CumulativeData* data);
+  void CreateHistogram(CumulativeData* data) const;
   // Reset the cumulative values, next time CreateHistogram is called it will recreate the cache.
   void Reset();
   double Mean() const;
diff --git a/runtime/gc/collector/garbage_collector.cc b/runtime/gc/collector/garbage_collector.cc
index 56d9ef4..cf301fe 100644
--- a/runtime/gc/collector/garbage_collector.cc
+++ b/runtime/gc/collector/garbage_collector.cc
@@ -21,6 +21,7 @@
 
 #include "garbage_collector.h"
 
+#include "base/histogram-inl.h"
 #include "base/logging.h"
 #include "base/mutex-inl.h"
 #include "gc/accounting/heap_bitmap.h"
@@ -40,6 +41,7 @@ GarbageCollector::GarbageCollector(Heap* heap, const std::string& name)
       verbose_(VLOG_IS_ON(heap)),
       duration_ns_(0),
       timings_(name_.c_str(), true, verbose_),
+      pause_histogram_((name_ + " paused").c_str(), kPauseBucketSize, kPauseBucketCount),
       cumulative_timings_(name) {
   ResetCumulativeStatistics();
 }
@@ -55,8 +57,8 @@ void GarbageCollector::RegisterPause(uint64_t nano_length) {
 
 void GarbageCollector::ResetCumulativeStatistics() {
   cumulative_timings_.Reset();
+  pause_histogram_.Reset();
   total_time_ns_ = 0;
-  total_paused_time_ns_ = 0;
   total_freed_objects_ = 0;
   total_freed_bytes_ = 0;
 }
@@ -86,8 +88,7 @@ void GarbageCollector::Run(bool clear_soft_references) {
     GetHeap()->RevokeAllThreadLocalBuffers();
     thread_list->ResumeAll();
     ATRACE_END();
-    uint64_t pause_end = NanoTime();
-    pause_times_.push_back(pause_end - pause_start);
+    RegisterPause(NanoTime() - pause_start);
   } else {
     Thread* self = Thread::Current();
     {
@@ -110,18 +111,20 @@ void GarbageCollector::Run(bool clear_soft_references) {
       ATRACE_BEGIN("Resuming mutator threads");
       thread_list->ResumeAll();
       ATRACE_END();
-      pause_times_.push_back(pause_end - pause_start);
+      RegisterPause(pause_end - pause_start);
     }
     {
       ReaderMutexLock mu(self, *Locks::mutator_lock_);
       ReclaimPhase();
     }
   }
-
+  FinishPhase();
   uint64_t end_time = NanoTime();
   duration_ns_ = end_time - start_time;
-
-  FinishPhase();
+  total_time_ns_ += GetDurationNs();
+  for (uint64_t pause_time : pause_times_) {
+    pause_histogram_.AddValue(pause_time / 1000);
+  }
 }
 
 void GarbageCollector::SwapBitmaps() {
diff --git a/runtime/gc/collector/garbage_collector.h b/runtime/gc/collector/garbage_collector.h
index a80f593..1779339 100644
--- a/runtime/gc/collector/garbage_collector.h
+++ b/runtime/gc/collector/garbage_collector.h
@@ -17,10 +17,10 @@
 #ifndef ART_RUNTIME_GC_COLLECTOR_GARBAGE_COLLECTOR_H_
 #define ART_RUNTIME_GC_COLLECTOR_GARBAGE_COLLECTOR_H_
 
+#include "base/histogram.h"
+#include "base/timing_logger.h"
 #include "gc_type.h"
 #include "locks.h"
-#include "base/timing_logger.h"
-
 #include <stdint.h>
 #include <vector>
 
@@ -95,7 +95,7 @@ class GarbageCollector {
   }
 
   uint64_t GetTotalPausedTimeNs() const {
-    return total_paused_time_ns_;
+    return pause_histogram_.Sum();
   }
 
   uint64_t GetTotalFreedBytes() const {
@@ -106,6 +106,10 @@ class GarbageCollector {
     return total_freed_objects_;
   }
 
+  const Histogram<uint64_t>& GetPauseHistogram() const {
+    return pause_histogram_;
+  }
+
  protected:
   // The initial phase. Done without mutators paused.
   virtual void InitializePhase() = 0;
@@ -122,6 +126,9 @@ class GarbageCollector {
   // Called after the GC is finished. Done without mutators paused.
   virtual void FinishPhase() = 0;
 
+  static constexpr size_t kPauseBucketSize = 500;
+  static constexpr size_t kPauseBucketCount = 32;
+
   Heap* const heap_;
 
   std::string name_;
@@ -134,8 +141,8 @@ class GarbageCollector {
   TimingLogger timings_;
 
   // Cumulative statistics.
+  Histogram<uint64_t> pause_histogram_;
   uint64_t total_time_ns_;
-  uint64_t total_paused_time_ns_;
   uint64_t total_freed_objects_;
   uint64_t total_freed_bytes_;
 
diff --git a/runtime/gc/collector/mark_sweep.cc b/runtime/gc/collector/mark_sweep.cc
index 58068b1..0697a65 100644
--- a/runtime/gc/collector/mark_sweep.cc
+++ b/runtime/gc/collector/mark_sweep.cc
@@ -1449,9 +1449,6 @@ void MarkSweep::FinishPhase() {
   heap->RequestHeapTrim();
 
   // Update the cumulative statistics
-  total_time_ns_ += GetDurationNs();
-  total_paused_time_ns_ += std::accumulate(GetPauseTimes().begin(), GetPauseTimes().end(), 0,
-                                           std::plus<uint64_t>());
   total_freed_objects_ += GetFreedObjects() + GetFreedLargeObjects();
   total_freed_bytes_ += GetFreedBytes() + GetFreedLargeObjectBytes();
 
diff --git a/runtime/gc/collector/semi_space.cc b/runtime/gc/collector/semi_space.cc
index 00794d6..3939354 100644
--- a/runtime/gc/collector/semi_space.cc
+++ b/runtime/gc/collector/semi_space.cc
@@ -584,9 +584,6 @@ void SemiSpace::FinishPhase() {
   from_space_ = nullptr;
 
   // Update the cumulative statistics
-  total_time_ns_ += GetDurationNs();
-  total_paused_time_ns_ += std::accumulate(GetPauseTimes().begin(), GetPauseTimes().end(), 0,
-                                           std::plus<uint64_t>());
   total_freed_objects_ += GetFreedObjects() + GetFreedLargeObjects();
   total_freed_bytes_ += GetFreedBytes() + GetFreedLargeObjectBytes();
 
diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc
index c31e3e9..ef9d157 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -23,6 +23,7 @@
 #include <vector>
 #include <valgrind.h>
 
+#include "base/histogram-inl.h"
 #include "base/stl_util.h"
 #include "common_throws.h"
 #include "cutils/sched_policy.h"
@@ -558,8 +559,10 @@ void Heap::DumpGcPerformanceInfo(std::ostream& os) {
       double seconds = NsToMs(logger.GetTotalNs()) / 1000.0;
       const uint64_t freed_bytes = collector->GetTotalFreedBytes();
       const uint64_t freed_objects = collector->GetTotalFreedObjects();
+      Histogram<uint64_t>::CumulativeData cumulative_data;
+      collector->GetPauseHistogram().CreateHistogram(&cumulative_data);
+      collector->GetPauseHistogram().PrintConfidenceIntervals(os, 0.99, cumulative_data);
       os << collector->GetName() << " total time: " << PrettyDuration(total_ns) << "\n"
-         << collector->GetName() << " paused time: " << PrettyDuration(total_pause_ns) << "\n"
          << collector->GetName() << " freed: " << freed_objects
          << " objects with total size " << PrettySize(freed_bytes) << "\n"
          << collector->GetName() << " throughput: " << freed_objects / seconds << "/s / "