Improve histogram and timing logger dumping.

We now dump the sum (total time) of each histogram as well as
previous stats. This is useful for the GC since the same split can
occur multiple times per GC iteration. Also did a few memory
optimizations by changing the map in the cumulative loggers
to be a set.

Bug: 11789200
Change-Id: I67bcc5384200924c8dc5d9eebcff077ce72b7e57

4 files changed, 52 insertions, 24 deletions

diff --git a/runtime/base/histogram-inl.h b/runtime/base/histogram-inl.h
index 9e08ae6..4cd68cd 100644
--- a/runtime/base/histogram-inl.h
+++ b/runtime/base/histogram-inl.h
@@ -39,6 +39,13 @@ template <class Value> inline void Histogram<Value>::AddValue(Value value) {
   BucketiseValue(value);
 }
 
+template <class Value> inline Histogram<Value>::Histogram(const char* name)
+    : kAdjust(0),
+      kInitialBucketCount(0),
+      name_(name),
+      max_buckets_(0) {
+}
+
 template <class Value>
 inline Histogram<Value>::Histogram(const char* name, Value initial_bucket_width,
                                    size_t max_buckets)
@@ -162,8 +169,9 @@ inline void Histogram<Value>::PrintConfidenceIntervals(std::ostream &os, double
 
   double per_0 = (1.0 - interval) / 2.0;
   double per_1 = per_0 + interval;
-  os << Name() << ":\t";
   TimeUnit unit = GetAppropriateTimeUnit(Mean() * kAdjust);
+  os << Name() << ":\tSum: ";
+  os << PrettyDuration(Sum() * kAdjust) << " ";
   os << (interval * 100) << "% C.I. " << FormatDuration(Percentile(per_0, data) * kAdjust, unit);
   os << "-" << FormatDuration(Percentile(per_1, data) * kAdjust, unit) << " ";
   os << "Avg: " << FormatDuration(Mean() * kAdjust, unit) << " Max: ";
diff --git a/runtime/base/histogram.h b/runtime/base/histogram.h
index e22b6e1..d4eb1f4 100644
--- a/runtime/base/histogram.h
+++ b/runtime/base/histogram.h
@@ -40,6 +40,8 @@ template <class Value> class Histogram {
     std::vector<double> perc_;
   };
 
+  // Used for name based comparators in the timing loggers.
+  explicit Histogram(const char* name);
   Histogram(const char* name, Value initial_bucket_width, size_t max_buckets = 100);
   void AddValue(Value);
   // Builds the cumulative distribution function from the frequency data.
diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc
index bebbd70..c8dee6d 100644
--- a/runtime/base/timing_logger.cc
+++ b/runtime/base/timing_logger.cc
@@ -39,7 +39,7 @@ CumulativeLogger::CumulativeLogger(const std::string& name)
 }
 
 CumulativeLogger::~CumulativeLogger() {
-  STLDeleteValues(&histograms_);
+  STLDeleteElements(&histograms_);
 }
 
 void CumulativeLogger::SetName(const std::string& name) {
@@ -57,7 +57,7 @@ void CumulativeLogger::End() {
 void CumulativeLogger::Reset() {
   MutexLock mu(Thread::Current(), lock_);
   iterations_ = 0;
-  STLDeleteValues(&histograms_);
+  STLDeleteElements(&histograms_);
 }
 
 uint64_t CumulativeLogger::GetTotalNs() const {
@@ -67,9 +67,8 @@ uint64_t CumulativeLogger::GetTotalNs() const {
 uint64_t CumulativeLogger::GetTotalTime() const {
   MutexLock mu(Thread::Current(), lock_);
   uint64_t total = 0;
-  for (CumulativeLogger::HistogramsIterator it = histograms_.begin(), end = histograms_.end();
-       it != end; ++it) {
-    total += it->second->Sum();
+  for (Histogram<uint64_t>* histogram : histograms_) {
+    total += histogram->Sum();
   }
   return total;
 }
@@ -95,30 +94,41 @@ void CumulativeLogger::Dump(std::ostream &os) {
   DumpHistogram(os);
 }
 
-void CumulativeLogger::AddPair(const std::string &label, uint64_t delta_time) {
+void CumulativeLogger::AddPair(const std::string& label, uint64_t delta_time) {
   // Convert delta time to microseconds so that we don't overflow our counters.
   delta_time /= kAdjust;
 
-  if (histograms_.find(label) == histograms_.end()) {
-    // TODO: Should this be a defined constant so we we know out of which orifice 16 and 100 were
-    //       picked?
-    const size_t max_buckets = Runtime::Current()->GetHeap()->IsLowMemoryMode() ? 16 : 100;
-    // TODO: Should this be a defined constant so we know 50 of WTF?
-    histograms_[label] = new Histogram<uint64_t>(label.c_str(), 50, max_buckets);
+  Histogram<uint64_t>* histogram;
+  Histogram<uint64_t> dummy(label.c_str());
+  auto it = histograms_.find(&dummy);
+  if (it == histograms_.end()) {
+    const size_t max_buckets = Runtime::Current()->GetHeap()->IsLowMemoryMode() ?
+        kLowMemoryBucketCount : kDefaultBucketCount;
+    histogram = new Histogram<uint64_t>(label.c_str(), kInitialBucketSize, max_buckets);
+    histograms_.insert(histogram);
+  } else {
+    histogram = *it;
   }
-  histograms_[label]->AddValue(delta_time);
+  histogram->AddValue(delta_time);
 }
 
+class CompareHistorgramByTimeSpentDeclining {
+ public:
+  bool operator()(const Histogram<uint64_t>* a, const Histogram<uint64_t>* b) const {
+    return a->Sum() > b->Sum();
+  }
+};
+
 void CumulativeLogger::DumpHistogram(std::ostream &os) {
   os << "Start Dumping histograms for " << iterations_ << " iterations"
      << " for " << name_ << "\n";
-  for (CumulativeLogger::HistogramsIterator it = histograms_.begin(), end = histograms_.end();
-       it != end; ++it) {
+  std::set<Histogram<uint64_t>*, CompareHistorgramByTimeSpentDeclining>
+      sorted_histograms(histograms_.begin(), histograms_.end());
+  for (Histogram<uint64_t>* histogram : sorted_histograms) {
     Histogram<uint64_t>::CumulativeData cumulative_data;
-    it->second->CreateHistogram(&cumulative_data);
-    it->second->PrintConfidenceIntervals(os, 0.99, cumulative_data);
-    // Reset cumulative values to save memory. We don't expect DumpHistogram to be called often, so
-    // it is not performance critical.
+    // We don't expect DumpHistogram to be called often, so it is not performance critical.
+    histogram->CreateHistogram(&cumulative_data);
+    histogram->PrintConfidenceIntervals(os, 0.99, cumulative_data);
   }
   os << "Done Dumping histograms \n";
 }
diff --git a/runtime/base/timing_logger.h b/runtime/base/timing_logger.h
index f1f7855..c1ff0a3 100644
--- a/runtime/base/timing_logger.h
+++ b/runtime/base/timing_logger.h
@@ -21,9 +21,9 @@
 #include "base/macros.h"
 #include "base/mutex.h"
 
+#include <set>
 #include <string>
 #include <vector>
-#include <map>
 
 namespace art {
 class TimingLogger;
@@ -45,15 +45,23 @@ class CumulativeLogger {
   size_t GetIterations() const;
 
  private:
-  typedef std::map<std::string, Histogram<uint64_t> *> Histograms;
-  typedef std::map<std::string, Histogram<uint64_t> *>::const_iterator HistogramsIterator;
+  class HistogramComparator {
+   public:
+    bool operator()(const Histogram<uint64_t>* a, const Histogram<uint64_t>* b) const {
+      return a->Name() < b->Name();
+    }
+  };
+
+  static constexpr size_t kLowMemoryBucketCount = 16;
+  static constexpr size_t kDefaultBucketCount = 100;
+  static constexpr size_t kInitialBucketSize = 50;  // 50 microseconds.
 
   void AddPair(const std::string &label, uint64_t delta_time)
       EXCLUSIVE_LOCKS_REQUIRED(lock_);
   void DumpHistogram(std::ostream &os) EXCLUSIVE_LOCKS_REQUIRED(lock_);
   uint64_t GetTotalTime() const;
   static const uint64_t kAdjust = 1000;
-  Histograms histograms_ GUARDED_BY(lock_);
+  std::set<Histogram<uint64_t>*, HistogramComparator> histograms_ GUARDED_BY(lock_);
   std::string name_;
   const std::string lock_name_;
   mutable Mutex lock_ DEFAULT_MUTEX_ACQUIRED_AFTER;