More advanced timing loggers.

The new timing loggers have lower overhead since they only push into
a vector. The new format has two types, a start timing and a stop
timing. You can thing of these as brackets associated with a
timestamp. It uses these to construct various statistics when needed,
such as: Total time, exclusive time, and nesting depth.

Changed PrettyDuration to have a default of 3 digits after the decimal
point.

Exaple of a GC dump with exclusive / total times and indenting:
I/art     (23546): GC iteration timing logger [Exclusive time] [Total time]
I/art     (23546):   0ms InitializePhase
I/art     (23546):   0.305ms/167.746ms MarkingPhase
I/art     (23546):     0ms BindBitmaps
I/art     (23546):     0ms FindDefaultSpaceBitmap
I/art     (23546):     0ms/1.709ms ProcessCards
I/art     (23546):       0.183ms ImageModUnionClearCards
I/art     (23546):       0.916ms ZygoteModUnionClearCards
I/art     (23546):       0.610ms AllocSpaceClearCards
I/art     (23546):       1.373ms AllocSpaceClearCards
I/art     (23546):     0.305ms/6.318ms MarkRoots
I/art     (23546):       2.106ms MarkRootsCheckpoint
I/art     (23546):       0.153ms MarkNonThreadRoots
I/art     (23546):       4.287ms MarkConcurrentRoots
I/art     (23546):     43.461ms UpdateAndMarkImageModUnionTable
I/art     (23546):     0ms/112.712ms RecursiveMark
I/art     (23546):       112.712ms ProcessMarkStack
I/art     (23546):     0.610ms/2.777ms PreCleanCards
I/art     (23546):       0.305ms/0.855ms ProcessCards
I/art     (23546):         0.153ms ImageModUnionClearCards
I/art     (23546):         0.610ms ZygoteModUnionClearCards
I/art     (23546):         0.610ms AllocSpaceClearCards
I/art     (23546):         0.549ms AllocSpaceClearCards
I/art     (23546):       0.549ms MarkRootsCheckpoint
I/art     (23546):       0.610ms MarkNonThreadRoots
I/art     (23546):       0ms MarkConcurrentRoots
I/art     (23546):       0.610ms ScanGrayImageSpaceObjects
I/art     (23546):       0.305ms ScanGrayZygoteSpaceObjects
I/art     (23546):       0.305ms ScanGrayAllocSpaceObjects
I/art     (23546):       1.129ms ScanGrayAllocSpaceObjects
I/art     (23546):       0ms ProcessMarkStack
I/art     (23546):   0ms/0.977ms (Paused)PausePhase
I/art     (23546):     0.244ms ReMarkRoots
I/art     (23546):     0.672ms (Paused)ScanGrayObjects
I/art     (23546):     0ms (Paused)ProcessMarkStack
I/art     (23546):     0ms/0.610ms SwapStacks
I/art     (23546):       0.610ms RevokeAllThreadLocalAllocationStacks
I/art     (23546):     0ms PreSweepingGcVerification
I/art     (23546):   0ms/10.621ms ReclaimPhase
I/art     (23546):     0.610ms/0.702ms ProcessReferences
I/art     (23546):       0.214ms/0.641ms EnqueueFinalizerReferences
I/art     (23546):         0.427ms ProcessMarkStack
I/art     (23546):     0.488ms SweepSystemWeaks
I/art     (23546):     0.824ms/9.400ms Sweep
I/art     (23546):       0ms SweepMallocSpace
I/art     (23546):       0.214ms SweepZygoteSpace
I/art     (23546):       0.122ms SweepMallocSpace
I/art     (23546):       6.226ms SweepMallocSpace
I/art     (23546):       0ms SweepMallocSpace
I/art     (23546):       2.144ms SweepLargeObjects
I/art     (23546):     0.305ms SwapBitmaps
I/art     (23546):     0ms UnBindBitmaps
I/art     (23546):   0.275ms FinishPhase
I/art     (23546): GC iteration timing logger: end, 178.971ms

Change-Id: Ia55b65609468f212b3cd65cda66b843da42be645

4 files changed, 298 insertions, 308 deletions

diff --git a/runtime/base/histogram-inl.h b/runtime/base/histogram-inl.h
index 7c0999992e..4c18ce405c 100644
--- a/runtime/base/histogram-inl.h
+++ b/runtime/base/histogram-inl.h
@@ -164,18 +164,18 @@ inline void Histogram<Value>::PrintBins(std::ostream& os, const CumulativeData&
 template <class Value>
 inline void Histogram<Value>::PrintConfidenceIntervals(std::ostream &os, double interval,
                                                        const CumulativeData& data) const {
+  static constexpr size_t kFractionalDigits = 3;
   DCHECK_GT(interval, 0);
   DCHECK_LT(interval, 1.0);
-
-  double per_0 = (1.0 - interval) / 2.0;
-  double per_1 = per_0 + interval;
-  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: ";
-  os << FormatDuration(Max() * kAdjust, unit) << "\n";
+  const double per_0 = (1.0 - interval) / 2.0;
+  const double per_1 = per_0 + interval;
+  const TimeUnit unit = GetAppropriateTimeUnit(Mean() * kAdjust);
+  os << Name() << ":\tSum: " << PrettyDuration(Sum() * kAdjust) << " "
+     << (interval * 100) << "% C.I. " << FormatDuration(Percentile(per_0, data) * kAdjust, unit,
+                                                        kFractionalDigits)
+     << "-" << FormatDuration(Percentile(per_1, data) * kAdjust, unit, kFractionalDigits) << " "
+     << "Avg: " << FormatDuration(Mean() * kAdjust, unit, kFractionalDigits) << " Max: "
+     << FormatDuration(Max() * kAdjust, unit, kFractionalDigits) << "\n";
 }
 
 template <class Value>
diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc
index a1550028e9..b6a2aaf33b 100644
--- a/runtime/base/timing_logger.cc
+++ b/runtime/base/timing_logger.cc
@@ -33,6 +33,8 @@ namespace art {
 
 constexpr size_t CumulativeLogger::kLowMemoryBucketCount;
 constexpr size_t CumulativeLogger::kDefaultBucketCount;
+constexpr size_t TimingLogger::kIndexNotFound;
+
 CumulativeLogger::CumulativeLogger(const std::string& name)
     : name_(name),
       lock_name_("CumulativeLoggerLock" + name),
@@ -66,10 +68,12 @@ void CumulativeLogger::Reset() {
 
 void CumulativeLogger::AddLogger(const TimingLogger &logger) {
   MutexLock mu(Thread::Current(), lock_);
-  for (const TimingLogger::SplitTiming& split : logger.GetSplits()) {
-    uint64_t split_time = split.first;
-    const char* split_name = split.second;
-    AddPair(split_name, split_time);
+  TimingLogger::TimingData timing_data(logger.CalculateTimingData());
+  const std::vector<TimingLogger::Timing>& timings = logger.GetTimings();
+  for (size_t i = 0; i < timings.size(); ++i) {
+    if (timings[i].IsStartTiming()) {
+      AddPair(timings[i].GetName(), timing_data.GetExclusiveTime(i));
+    }
   }
   ++iterations_;
 }
@@ -124,166 +128,125 @@ void CumulativeLogger::DumpHistogram(std::ostream &os) const {
 }
 
 TimingLogger::TimingLogger(const char* name, bool precise, bool verbose)
-    : name_(name), precise_(precise), verbose_(verbose), current_split_(NULL) {
+    : name_(name), precise_(precise), verbose_(verbose) {
 }
 
 void TimingLogger::Reset() {
-  current_split_ = NULL;
-  splits_.clear();
+  timings_.clear();
 }
 
-void TimingLogger::StartSplit(const char* new_split_label) {
-  DCHECK(new_split_label != nullptr) << "Starting split with null label.";
-  TimingLogger::ScopedSplit* explicit_scoped_split =
-      new TimingLogger::ScopedSplit(new_split_label, this);
-  explicit_scoped_split->explicit_ = true;
+void TimingLogger::StartTiming(const char* label) {
+  DCHECK(label != nullptr);
+  timings_.push_back(Timing(NanoTime(), label));
+  ATRACE_BEGIN(label);
 }
 
-void TimingLogger::EndSplit() {
-  CHECK(current_split_ != nullptr) << "Ending a non-existent split.";
-  DCHECK(current_split_->label_ != nullptr);
-  DCHECK(current_split_->explicit_ == true)
-      << "Explicitly ending scoped split: " << current_split_->label_;
-  delete current_split_;
-  // TODO: current_split_ = nullptr;
+void TimingLogger::EndTiming() {
+  timings_.push_back(Timing(NanoTime(), nullptr));
+  ATRACE_END();
 }
 
-// Ends the current split and starts the one given by the label.
-void TimingLogger::NewSplit(const char* new_split_label) {
-  if (current_split_ == nullptr) {
-    StartSplit(new_split_label);
-  } else {
-    DCHECK(new_split_label != nullptr) << "New split (" << new_split_label << ") with null label.";
-    current_split_->TailInsertSplit(new_split_label);
+uint64_t TimingLogger::GetTotalNs() const {
+  if (timings_.size() < 2) {
+    return 0;
   }
+  return timings_.back().GetTime() - timings_.front().GetTime();
 }
 
-uint64_t TimingLogger::GetTotalNs() const {
-  uint64_t total_ns = 0;
-  for (const TimingLogger::SplitTiming& split : splits_) {
-    total_ns += split.first;
+size_t TimingLogger::FindTimingIndex(const char* name, size_t start_idx) const {
+  DCHECK_LT(start_idx, timings_.size());
+  for (size_t i = start_idx; i < timings_.size(); ++i) {
+    if (timings_[i].IsStartTiming() && strcmp(timings_[i].GetName(), name) == 0) {
+      return i;
+    }
   }
-  return total_ns;
+  return kIndexNotFound;
+}
+
+TimingLogger::TimingData TimingLogger::CalculateTimingData() const {
+  TimingLogger::TimingData ret;
+  ret.data_.resize(timings_.size());
+  std::vector<size_t> open_stack;
+  for (size_t i = 0; i < timings_.size(); ++i) {
+    if (timings_[i].IsEndTiming()) {
+      CHECK(!open_stack.empty()) << "No starting split for ending split at index " << i;
+      size_t open_idx = open_stack.back();
+      uint64_t time = timings_[i].GetTime() - timings_[open_idx].GetTime();
+      ret.data_[open_idx].exclusive_time += time;
+      DCHECK_EQ(ret.data_[open_idx].total_time, 0U);
+      ret.data_[open_idx].total_time += time;
+      // Each open split has exactly one end.
+      open_stack.pop_back();
+      // If there is a parent node, subtract from the exclusive time.
+      if (!open_stack.empty()) {
+        // Note this may go negative, but will work due to 2s complement when we add the value
+        // total time value later.
+        ret.data_[open_stack.back()].exclusive_time -= time;
+      }
+    } else {
+      open_stack.push_back(i);
+    }
+  }
+  CHECK(open_stack.empty()) << "Missing ending for timing "
+      << timings_[open_stack.back()].GetName() << " at index " << open_stack.back();
+  return ret;  // No need to fear, C++11 move semantics are here.
 }
 
-void TimingLogger::Dump(std::ostream &os) const {
+void TimingLogger::Dump(std::ostream &os, const char* indent_string) const {
+  static constexpr size_t kFractionalDigits = 3;
+  TimingLogger::TimingData timing_data(CalculateTimingData());
   uint64_t longest_split = 0;
-  uint64_t total_ns = 0;
-  for (const SplitTiming& split : splits_) {
-    uint64_t split_time = split.first;
-    longest_split = std::max(longest_split, split_time);
-    total_ns += split_time;
+  for (size_t i = 0; i < timings_.size(); ++i) {
+    longest_split = std::max(longest_split, timing_data.GetTotalTime(i));
   }
   // Compute which type of unit we will use for printing the timings.
   TimeUnit tu = GetAppropriateTimeUnit(longest_split);
   uint64_t divisor = GetNsToTimeUnitDivisor(tu);
+  uint64_t mod_fraction = divisor >= 1000 ? divisor / 1000 : 1;
   // Print formatted splits.
-  for (const SplitTiming& split : splits_) {
-    uint64_t split_time = split.first;
-    if (!precise_ && divisor >= 1000) {
-      // Make the fractional part 0.
-      split_time -= split_time % (divisor / 1000);
+  size_t tab_count = 1;
+  os << name_ << " [Exclusive time] [Total time]\n";
+  for (size_t i = 0; i < timings_.size(); ++i) {
+    if (timings_[i].IsStartTiming()) {
+      uint64_t exclusive_time = timing_data.GetExclusiveTime(i);
+      uint64_t total_time = timing_data.GetTotalTime(i);
+      if (!precise_) {
+        // Make the fractional part 0.
+        exclusive_time -= exclusive_time % mod_fraction;
+        total_time -= total_time % mod_fraction;
+      }
+      for (size_t j = 0; j < tab_count; ++j) {
+        os << indent_string;
+      }
+      os << FormatDuration(exclusive_time, tu, kFractionalDigits);
+      // If they are the same, just print one value to prevent spam.
+      if (exclusive_time != total_time) {
+        os << "/" << FormatDuration(total_time, tu, kFractionalDigits);
+      }
+      os << " " << timings_[i].GetName() << "\n";
+      ++tab_count;
+    } else {
+      --tab_count;
     }
-    os << name_ << ": " << std::setw(8) << FormatDuration(split_time, tu) << " "
-       << split.second << "\n";
   }
-  os << name_ << ": end, " << NsToMs(total_ns) << " ms\n";
+  os << name_ << ": end, " << PrettyDuration(GetTotalNs()) << "\n";
 }
 
-TimingLogger::ScopedSplit::ScopedSplit(const char* label, TimingLogger* timing_logger) {
-  DCHECK(label != NULL) << "New scoped split (" << label << ") with null label.";
-  CHECK(timing_logger != NULL) << "New scoped split (" << label << ") without TimingLogger.";
-  timing_logger_ = timing_logger;
-  label_ = label;
-  running_ns_ = 0;
-  explicit_ = false;
-
-  // Stash away the current split and pause it.
-  enclosing_split_ = timing_logger->current_split_;
-  if (enclosing_split_ != NULL) {
-    enclosing_split_->Pause();
-  }
-
-  timing_logger_->current_split_ = this;
-
-  ATRACE_BEGIN(label_);
-
-  start_ns_ = NanoTime();
-  if (timing_logger_->verbose_) {
-    LOG(INFO) << "Begin: " << label_;
-  }
-}
-
-TimingLogger::ScopedSplit::~ScopedSplit() {
-  uint64_t current_time = NanoTime();
-  uint64_t split_time = current_time - start_ns_;
-  running_ns_ += split_time;
-  ATRACE_END();
-
-  if (timing_logger_->verbose_) {
-    LOG(INFO) << "End: " << label_ << " " << PrettyDuration(split_time);
-  }
-
-  // If one or more enclosed explicitly started splits are not terminated we can
-  // either fail or "unwind" the stack of splits in the timing logger to 'this'
-  // (by deleting the intervening scoped splits). This implements the latter.
-  TimingLogger::ScopedSplit* current = timing_logger_->current_split_;
-  while ((current != NULL) && (current != this)) {
-    delete current;
-    current = timing_logger_->current_split_;
-  }
-
-  CHECK(current != NULL) << "Missing scoped split (" << this->label_
-                           << ") in timing logger (" << timing_logger_->name_ << ").";
-  CHECK(timing_logger_->current_split_ == this);
-
-  timing_logger_->splits_.push_back(SplitTiming(running_ns_, label_));
-
-  timing_logger_->current_split_ = enclosing_split_;
-  if (enclosing_split_ != NULL) {
-    enclosing_split_->Resume();
+void TimingLogger::Verify() {
+  size_t counts[2] = { 0 };
+  for (size_t i = 0; i < timings_.size(); ++i) {
+    if (i > 0) {
+      CHECK_LE(timings_[i - 1].GetTime(), timings_[i].GetTime());
+    }
+    ++counts[timings_[i].IsStartTiming() ? 0 : 1];
   }
+  CHECK_EQ(counts[0], counts[1]) << "Number of StartTiming and EndTiming doesn't match";
 }
 
-
-void TimingLogger::ScopedSplit::TailInsertSplit(const char* label) {
-  // Sleight of hand here: Rather than embedding a new scoped split, we're updating the current
-  // scoped split in place. Basically, it's one way to make explicit and scoped splits compose
-  // well while maintaining the current semantics of NewSplit. An alternative is to push a new split
-  // since we unwind the stack of scoped splits in the scoped split destructor. However, this implies
-  // that the current split is not ended by NewSplit (which calls TailInsertSplit), which would
-  // be different from what we had before.
-
-  uint64_t current_time = NanoTime();
-  uint64_t split_time = current_time - start_ns_;
-  ATRACE_END();
-  timing_logger_->splits_.push_back(std::pair<uint64_t, const char*>(split_time, label_));
-
-  if (timing_logger_->verbose_) {
-    LOG(INFO) << "End: " << label_ << " " << PrettyDuration(split_time) << "\n"
-              << "Begin: " << label;
+TimingLogger::~TimingLogger() {
+  if (kIsDebugBuild) {
+    Verify();
   }
-
-  label_ = label;
-  start_ns_ = current_time;
-  running_ns_ = 0;
-
-  ATRACE_BEGIN(label);
-}
-
-void TimingLogger::ScopedSplit::Pause() {
-  uint64_t current_time = NanoTime();
-  uint64_t split_time = current_time - start_ns_;
-  running_ns_ += split_time;
-  ATRACE_END();
-}
-
-
-void TimingLogger::ScopedSplit::Resume() {
-  uint64_t current_time = NanoTime();
-
-  start_ns_ = current_time;
-  ATRACE_BEGIN(label_);
 }
 
 }  // namespace art
diff --git a/runtime/base/timing_logger.h b/runtime/base/timing_logger.h
index 9b558980c5..b300109e31 100644
--- a/runtime/base/timing_logger.h
+++ b/runtime/base/timing_logger.h
@@ -77,93 +77,119 @@ class CumulativeLogger {
 // A timing logger that knows when a split starts for the purposes of logging tools, like systrace.
 class TimingLogger {
  public:
-  // Splits are nanosecond times and split names.
-  typedef std::pair<uint64_t, const char*> SplitTiming;
-  typedef std::vector<SplitTiming> SplitTimings;
+  static constexpr size_t kIndexNotFound = static_cast<size_t>(-1);
 
-  explicit TimingLogger(const char* name, bool precise, bool verbose);
-  ~TimingLogger() {
-    // TODO: DCHECK(current_split_ == nullptr) << "Forgot to end split: " << current_split_->label_;
-  }
-  // Clears current splits and labels.
-  void Reset();
+  class Timing {
+   public:
+    Timing(uint64_t time, const char* name) : time_(time), name_(name) {
+    }
+    bool IsStartTiming() const {
+      return !IsEndTiming();
+    }
+    bool IsEndTiming() const {
+      return name_ == nullptr;
+    }
+    uint64_t GetTime() const {
+      return time_;
+    }
+    const char* GetName() const {
+      return name_;
+    }
 
-  // Starts a split
-  void StartSplit(const char* new_split_label);
+   private:
+    uint64_t time_;
+    const char* name_;
+  };
 
-  // Ends the current split and starts the one given by the label.
-  void NewSplit(const char* new_split_label);
+  // Extra data that is only calculated when you call dump to prevent excess allocation.
+  class TimingData {
+   public:
+    TimingData() = default;
+    TimingData(TimingData&& other) {
+      std::swap(data_, other.data_);
+    }
+    TimingData& operator=(TimingData&& other) {
+      std::swap(data_, other.data_);
+      return *this;
+    }
+    uint64_t GetTotalTime(size_t idx) {
+      return data_[idx].total_time;
+    }
+    uint64_t GetExclusiveTime(size_t idx) {
+      return data_[idx].exclusive_time;
+    }
 
-  // Ends the current split and records the end time.
-  void EndSplit();
+   private:
+    // Each begin split has a total time and exclusive time. Exclusive time is total time - total
+    // time of children nodes.
+    struct CalculatedDataPoint {
+      CalculatedDataPoint() : total_time(0), exclusive_time(0) {}
+      uint64_t total_time;
+      uint64_t exclusive_time;
+    };
+    std::vector<CalculatedDataPoint> data_;
+    friend class TimingLogger;
+  };
 
+  explicit TimingLogger(const char* name, bool precise, bool verbose);
+  ~TimingLogger();
+  // Verify that all open timings have related closed timings.
+  void Verify();
+  // Clears current timings and labels.
+  void Reset();
+  // Starts a timing.
+  void StartTiming(const char* new_split_label);
+  // Ends the current timing.
+  void EndTiming();
+  // End the current timing and start a new timing. Usage not recommended.
+  void NewTiming(const char* new_split_label) {
+    EndTiming();
+    StartTiming(new_split_label);
+  }
+  // Returns the total duration of the timings (sum of total times).
   uint64_t GetTotalNs() const;
-
-  void Dump(std::ostream& os) const;
+  // Find the index of a timing by name.
+  size_t FindTimingIndex(const char* name, size_t start_idx) const;
+  void Dump(std::ostream& os, const char* indent_string = "  ") const;
 
   // Scoped timing splits that can be nested and composed with the explicit split
   // starts and ends.
-  class ScopedSplit {
-    public:
-      explicit ScopedSplit(const char* label, TimingLogger* timing_logger);
-
-      ~ScopedSplit();
-
-      friend class TimingLogger;
-
-    private:
-      // Pauses timing of the split, usually due to nesting of another split.
-      void Pause();
-
-      // Resumes timing of the split, usually because a nested split has ended.
-      void Resume();
-
-      // Used by new split to swap splits in place in a ScopedSplit instance.
-      void TailInsertSplit(const char* label);
-
-      // The scoped split immediately enclosing this split. Essentially, we get a
-      // stack of nested splits through this field.
-      ScopedSplit* enclosing_split_;
-
-      // Was this created via TimingLogger's StartSplit?
-      bool explicit_;
-
-      // The split's name.
-      const char* label_;
-
-      // The current split's latest start time. (It may have been paused and restarted.)
-      uint64_t start_ns_;
-
-      // The running time, outside of pauses.
-      uint64_t running_ns_;
-
-      // The timing logger holding this split.
-      TimingLogger* timing_logger_;
+  class ScopedTiming {
+   public:
+    explicit ScopedTiming(const char* label, TimingLogger* logger) : logger_(logger) {
+      logger_->StartTiming(label);
+    }
+    ~ScopedTiming() {
+      logger_->EndTiming();
+    }
+    // Closes the current timing and opens a new timing.
+    void NewTiming(const char* label) {
+      logger_->NewTiming(label);
+    }
 
-      DISALLOW_COPY_AND_ASSIGN(ScopedSplit);
+   private:
+    TimingLogger* const logger_;  // The timing logger which the scoped timing is associated with.
+    DISALLOW_COPY_AND_ASSIGN(ScopedTiming);
   };
 
-  const SplitTimings& GetSplits() const {
-    return splits_;
+  // Return the time points of when each start / end timings start and finish.
+  const std::vector<Timing>& GetTimings() const {
+    return timings_;
   }
 
-  friend class ScopedSplit;
+  TimingData CalculateTimingData() const;
+
  protected:
   // The name of the timing logger.
   const char* const name_;
-
   // Do we want to print the exactly recorded split (true) or round down to the time unit being
   // used (false).
   const bool precise_;
-
   // Verbose logging.
   const bool verbose_;
-
-  // The current scoped split is also the 'top' of the stack of splits in progress.
-  ScopedSplit* current_split_;
-
-  // Splits that have ended.
-  SplitTimings splits_;
+  // Timing points that are either start or end points. For each starting point ret[i] = location
+  // of end split associated with i. If it is and end split ret[i] = i.
+  std::vector<Timing> timings_;
 
  private:
   DISALLOW_COPY_AND_ASSIGN(TimingLogger);
diff --git a/runtime/base/timing_logger_test.cc b/runtime/base/timing_logger_test.cc
index 0757751822..35a73d0a76 100644
--- a/runtime/base/timing_logger_test.cc
+++ b/runtime/base/timing_logger_test.cc
@@ -26,16 +26,14 @@ class TimingLoggerTest : public CommonRuntimeTest {};
 
 TEST_F(TimingLoggerTest, StartEnd) {
   const char* split1name = "First Split";
-  TimingLogger timings("StartEnd", true, false);
-
-  timings.StartSplit(split1name);
-
-  timings.EndSplit();  // Ends split1.
-
-  const TimingLogger::SplitTimings& splits = timings.GetSplits();
-
-  EXPECT_EQ(1U, splits.size());
-  EXPECT_STREQ(splits[0].second, split1name);
+  TimingLogger logger("StartEnd", true, false);
+  logger.StartTiming(split1name);
+  logger.EndTiming();  // Ends split1.
+  const auto& timings = logger.GetTimings();
+  EXPECT_EQ(2U, timings.size());  // Start, End splits
+  EXPECT_TRUE(timings[0].IsStartTiming());
+  EXPECT_STREQ(timings[0].GetName(), split1name);
+  EXPECT_TRUE(timings[1].IsEndTiming());
 }
 
 
@@ -43,56 +41,61 @@ TEST_F(TimingLoggerTest, StartNewEnd) {
   const char* split1name = "First Split";
   const char* split2name = "Second Split";
   const char* split3name = "Third Split";
-  TimingLogger timings("StartNewEnd", true, false);
-
-  timings.StartSplit(split1name);
-
-  timings.NewSplit(split2name);  // Ends split1.
-
-  timings.NewSplit(split3name);  // Ends split2.
-
-  timings.EndSplit();  // Ends split3.
-
-  const TimingLogger::SplitTimings& splits = timings.GetSplits();
-
-  EXPECT_EQ(3U, splits.size());
-  EXPECT_STREQ(splits[0].second, split1name);
-  EXPECT_STREQ(splits[1].second, split2name);
-  EXPECT_STREQ(splits[2].second, split3name);
+  TimingLogger logger("StartNewEnd", true, false);
+  logger.StartTiming(split1name);
+  logger.NewTiming(split2name);
+  logger.NewTiming(split3name);
+  logger.EndTiming();
+  // Get the timings and verify that they are sane.
+  const auto& timings = logger.GetTimings();
+  // 6 timings in the timing logger at this point.
+  EXPECT_EQ(6U, timings.size());
+  EXPECT_TRUE(timings[0].IsStartTiming());
+  EXPECT_STREQ(timings[0].GetName(), split1name);
+  EXPECT_TRUE(timings[1].IsEndTiming());
+  EXPECT_TRUE(timings[2].IsStartTiming());
+  EXPECT_STREQ(timings[2].GetName(), split2name);
+  EXPECT_TRUE(timings[3].IsEndTiming());
+  EXPECT_TRUE(timings[4].IsStartTiming());
+  EXPECT_STREQ(timings[4].GetName(), split3name);
+  EXPECT_TRUE(timings[5].IsEndTiming());
 }
 
 TEST_F(TimingLoggerTest, StartNewEndNested) {
-  const char* split1name = "First Split";
-  const char* split2name = "Second Split";
-  const char* split3name = "Third Split";
-  const char* split4name = "Fourth Split";
-  const char* split5name = "Fifth Split";
-  TimingLogger timings("StartNewEndNested", true, false);
-
-  timings.StartSplit(split1name);
-
-  timings.NewSplit(split2name);  // Ends split1.
-
-  timings.StartSplit(split3name);
-
-  timings.StartSplit(split4name);
-
-  timings.NewSplit(split5name);  // Ends split4.
-
-  timings.EndSplit();  // Ends split5.
-
-  timings.EndSplit();  // Ends split3.
-
-  timings.EndSplit();  // Ends split2.
-
-  const TimingLogger::SplitTimings& splits = timings.GetSplits();
-
-  EXPECT_EQ(5U, splits.size());
-  EXPECT_STREQ(splits[0].second, split1name);
-  EXPECT_STREQ(splits[1].second, split4name);
-  EXPECT_STREQ(splits[2].second, split5name);
-  EXPECT_STREQ(splits[3].second, split3name);
-  EXPECT_STREQ(splits[4].second, split2name);
+  const char* name1 = "First Split";
+  const char* name2 = "Second Split";
+  const char* name3 = "Third Split";
+  const char* name4 = "Fourth Split";
+  const char* name5 = "Fifth Split";
+  TimingLogger logger("StartNewEndNested", true, false);
+  logger.StartTiming(name1);
+  logger.NewTiming(name2);  // Ends timing1.
+  logger.StartTiming(name3);
+  logger.StartTiming(name4);
+  logger.NewTiming(name5);  // Ends timing4.
+  logger.EndTiming();  // Ends timing5.
+  logger.EndTiming();  // Ends timing3.
+  logger.EndTiming();  // Ends timing2.
+  const auto& timings = logger.GetTimings();
+  EXPECT_EQ(10U, timings.size());
+  size_t idx_1 = logger.FindTimingIndex(name1, 0);
+  size_t idx_2 = logger.FindTimingIndex(name2, 0);
+  size_t idx_3 = logger.FindTimingIndex(name3, 0);
+  size_t idx_4 = logger.FindTimingIndex(name4, 0);
+  size_t idx_5 = logger.FindTimingIndex(name5, 0);
+  size_t idx_6 = logger.FindTimingIndex("Not found", 0);
+  EXPECT_NE(idx_1, TimingLogger::kIndexNotFound);
+  EXPECT_NE(idx_2, TimingLogger::kIndexNotFound);
+  EXPECT_NE(idx_3, TimingLogger::kIndexNotFound);
+  EXPECT_NE(idx_4, TimingLogger::kIndexNotFound);
+  EXPECT_NE(idx_5, TimingLogger::kIndexNotFound);
+  EXPECT_EQ(idx_6, TimingLogger::kIndexNotFound);
+  TimingLogger::TimingData data = logger.CalculateTimingData();
+  EXPECT_STREQ(timings[idx_1].GetName(), name1);
+  EXPECT_STREQ(timings[idx_2].GetName(), name2);
+  EXPECT_STREQ(timings[idx_3].GetName(), name3);
+  EXPECT_STREQ(timings[idx_4].GetName(), name4);
+  EXPECT_STREQ(timings[idx_5].GetName(), name5);
 }
 
 
@@ -101,31 +104,32 @@ TEST_F(TimingLoggerTest, Scoped) {
   const char* innersplit1 = "Inner Split 1";
   const char* innerinnersplit1 = "Inner Inner Split 1";
   const char* innersplit2 = "Inner Split 2";
-  TimingLogger timings("Scoped", true, false);
-
+  TimingLogger logger("Scoped", true, false);
   {
-      TimingLogger::ScopedSplit outer(outersplit, &timings);
-
-      {
-          TimingLogger::ScopedSplit inner1(innersplit1, &timings);
-
-          {
-              TimingLogger::ScopedSplit innerinner1(innerinnersplit1, &timings);
-          }  // Ends innerinnersplit1.
-      }  // Ends innersplit1.
-
+    TimingLogger::ScopedTiming outer(outersplit, &logger);
+    {
+      TimingLogger::ScopedTiming inner1(innersplit1, &logger);
       {
-          TimingLogger::ScopedSplit inner2(innersplit2, &timings);
-      }  // Ends innersplit2.
+        TimingLogger::ScopedTiming innerinner1(innerinnersplit1, &logger);
+      }  // Ends innerinnersplit1.
+    }  // Ends innersplit1.
+    {
+      TimingLogger::ScopedTiming inner2(innersplit2, &logger);
+    }  // Ends innersplit2.
   }  // Ends outersplit.
-
-  const TimingLogger::SplitTimings& splits = timings.GetSplits();
-
-  EXPECT_EQ(4U, splits.size());
-  EXPECT_STREQ(splits[0].second, innerinnersplit1);
-  EXPECT_STREQ(splits[1].second, innersplit1);
-  EXPECT_STREQ(splits[2].second, innersplit2);
-  EXPECT_STREQ(splits[3].second, outersplit);
+  const size_t idx_outersplit = logger.FindTimingIndex(outersplit, 0);
+  const size_t idx_innersplit1 = logger.FindTimingIndex(innersplit1, 0);
+  const size_t idx_innerinnersplit1 = logger.FindTimingIndex(innerinnersplit1, 0);
+  const size_t idx_innersplit2 = logger.FindTimingIndex(innersplit2, 0);
+  const auto& timings = logger.GetTimings();
+  EXPECT_EQ(8U, timings.size());  // 4 start timings and 4 end timings.
+  EXPECT_GE(timings[idx_innerinnersplit1].GetTime(), timings[idx_innersplit1].GetTime());
+  EXPECT_GE(timings[idx_innersplit2].GetTime(), timings[idx_innersplit1].GetTime());
+  TimingLogger::TimingData data(logger.CalculateTimingData());
+  EXPECT_GE(data.GetTotalTime(idx_outersplit), data.GetTotalTime(idx_innerinnersplit1));
+  EXPECT_GE(data.GetTotalTime(idx_outersplit),
+            data.GetTotalTime(idx_innersplit1) + data.GetTotalTime(idx_innersplit2));
+  EXPECT_GE(data.GetTotalTime(idx_innersplit1), data.GetTotalTime(idx_innerinnersplit1));
 }
 
 
@@ -134,27 +138,24 @@ TEST_F(TimingLoggerTest, ScopedAndExplicit) {
   const char* innersplit = "Inner Split";
   const char* innerinnersplit1 = "Inner Inner Split 1";
   const char* innerinnersplit2 = "Inner Inner Split 2";
-  TimingLogger timings("Scoped", true, false);
-
-  timings.StartSplit(outersplit);
-
+  TimingLogger logger("Scoped", true, false);
+  logger.StartTiming(outersplit);
   {
-      TimingLogger::ScopedSplit inner(innersplit, &timings);
-
-      timings.StartSplit(innerinnersplit1);
-
-      timings.NewSplit(innerinnersplit2);  // Ends innerinnersplit1.
+    TimingLogger::ScopedTiming inner(innersplit, &logger);
+    logger.StartTiming(innerinnersplit1);
+    logger.NewTiming(innerinnersplit2);  // Ends innerinnersplit1.
+    logger.EndTiming();
   }  // Ends innerinnersplit2, then innersplit.
-
-  timings.EndSplit();  // Ends outersplit.
-
-  const TimingLogger::SplitTimings& splits = timings.GetSplits();
-
-  EXPECT_EQ(4U, splits.size());
-  EXPECT_STREQ(splits[0].second, innerinnersplit1);
-  EXPECT_STREQ(splits[1].second, innerinnersplit2);
-  EXPECT_STREQ(splits[2].second, innersplit);
-  EXPECT_STREQ(splits[3].second, outersplit);
+  logger.EndTiming();  // Ends outersplit.
+  const size_t idx_outersplit = logger.FindTimingIndex(outersplit, 0);
+  const size_t idx_innersplit = logger.FindTimingIndex(innersplit, 0);
+  const size_t idx_innerinnersplit1 = logger.FindTimingIndex(innerinnersplit1, 0);
+  const size_t idx_innerinnersplit2 = logger.FindTimingIndex(innerinnersplit2, 0);
+  const auto& timings = logger.GetTimings();
+  EXPECT_EQ(8U, timings.size());
+  EXPECT_LE(timings[idx_outersplit].GetTime(), timings[idx_innersplit].GetTime());
+  EXPECT_LE(timings[idx_innersplit].GetTime(), timings[idx_innerinnersplit1].GetTime());
+  EXPECT_LE(timings[idx_innerinnersplit1].GetTime(), timings[idx_innerinnersplit2].GetTime());
 }
 
 }  // namespace art