Systrace fixups and refactoring for TimingLogger

Fixed systrace bounds for timing logger in GC. Refactored CumulativeLogger a bit to
allow for multiple identical entries. Added ScopedSplit, now composes with explicit
start/end/new splits. Adds some unit tests.
Bug: 10036801

Change-Id: If0afb88b48ec3a1e19462ed354babb274a9517a7

7 files changed, 484 insertions, 159 deletions

diff --git a/build/Android.gtest.mk b/build/Android.gtest.mk
index ac3b821333..498f7ef11b 100644
--- a/build/Android.gtest.mk
+++ b/build/Android.gtest.mk
@@ -25,6 +25,7 @@ TEST_COMMON_SRC_FILES := \
 	runtime/barrier_test.cc \
 	runtime/base/histogram_test.cc \
 	runtime/base/mutex_test.cc \
+	runtime/base/timing_logger_test.cc \
 	runtime/base/unix_file/fd_file_test.cc \
 	runtime/base/unix_file/mapped_file_test.cc \
 	runtime/base/unix_file/null_file_test.cc \
diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc
index b58b0ac722..78a6883f0b 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() {
-  STLDeleteElements(&histograms_);
+  STLDeleteValues(&histograms_);
 }
 
 void CumulativeLogger::SetName(const std::string& name) {
@@ -47,18 +47,17 @@ void CumulativeLogger::SetName(const std::string& name) {
 }
 
 void CumulativeLogger::Start() {
-  MutexLock mu(Thread::Current(), lock_);
-  index_ = 0;
 }
 
 void CumulativeLogger::End() {
   MutexLock mu(Thread::Current(), lock_);
   iterations_++;
 }
+
 void CumulativeLogger::Reset() {
   MutexLock mu(Thread::Current(), lock_);
   iterations_ = 0;
-  STLDeleteElements(&histograms_);
+  STLDeleteValues(&histograms_);
 }
 
 uint64_t CumulativeLogger::GetTotalNs() const {
@@ -68,36 +67,19 @@ uint64_t CumulativeLogger::GetTotalNs() const {
 uint64_t CumulativeLogger::GetTotalTime() const {
   MutexLock mu(Thread::Current(), lock_);
   uint64_t total = 0;
-  for (size_t i = 0; i < histograms_.size(); ++i) {
-    total += histograms_[i]->Sum();
+  for (CumulativeLogger::HistogramsIterator it = histograms_.begin(), end = histograms_.end();
+       it != end; ++it) {
+    total += it->second->Sum();
   }
   return total;
 }
 
-
 void CumulativeLogger::AddLogger(const base::TimingLogger &logger) {
   MutexLock mu(Thread::Current(), lock_);
-  const std::vector<std::pair<uint64_t, const char*> >& splits = logger.GetSplits();
-  typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It;
-  // The first time this is run, the histograms array will be empty.
-  if (kIsDebugBuild && !histograms_.empty() && splits.size() != histograms_.size()) {
-    LOG(ERROR) << "Mismatch in splits.";
-    typedef std::vector<Histogram<uint64_t> *>::const_iterator It2;
-    It it = splits.begin();
-    It2 it2 = histograms_.begin();
-    while ((it != splits.end()) && (it2 != histograms_.end())) {
-      if (it != splits.end()) {
-        LOG(ERROR) << "\tsplit: " << it->second;
-        ++it;
-      }
-      if (it2 != histograms_.end()) {
-        LOG(ERROR) << "\tpreviously record: " << (*it2)->Name();
-        ++it2;
-      }
-    }
-  }
-  for (It it = splits.begin(), end = splits.end(); it != end; ++it) {
-    std::pair<uint64_t, const char*> split = *it;
+  const base::TimingLogger::SplitTimings& splits = logger.GetSplits();
+  for (base::TimingLogger::SplitsIterator it = splits.begin(), end = splits.end();
+       it != end; ++it) {
+    base::TimingLogger::SplitTiming split = *it;
     uint64_t split_time = split.first;
     const char* split_name = split.second;
     AddPair(split_name, split_time);
@@ -112,23 +94,24 @@ void CumulativeLogger::Dump(std::ostream &os) {
 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_.size() <= index_) {
+
+  if (histograms_.find(label) == histograms_.end()) {
+    // TODO: Shoud 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;
-    histograms_.push_back(new Histogram<uint64_t>(label.c_str(), 50, max_buckets));
-    DCHECK_GT(histograms_.size(), index_);
+    // 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);
   }
-  histograms_[index_]->AddValue(delta_time);
-  DCHECK_EQ(label, histograms_[index_]->Name());
-  ++index_;
+  histograms_[label]->AddValue(delta_time);
 }
 
 void CumulativeLogger::DumpHistogram(std::ostream &os) {
   os << "Start Dumping histograms for " << iterations_ << " iterations"
      << " for " << name_ << "\n";
-  for (size_t Idx = 0; Idx < histograms_.size(); Idx++) {
+  for (CumulativeLogger::HistogramsIterator it = histograms_.begin(), end = histograms_.end();
+       it != end; ++it) {
     Histogram<uint64_t>::CumulativeData cumulative_data;
-    histograms_[Idx]->CreateHistogram(cumulative_data);
-    histograms_[Idx]->PrintConfidenceIntervals(os, 0.99, 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.
   }
@@ -139,58 +122,42 @@ void CumulativeLogger::DumpHistogram(std::ostream &os) {
 namespace base {
 
 TimingLogger::TimingLogger(const char* name, bool precise, bool verbose)
-    : name_(name), precise_(precise), verbose_(verbose),
-      current_split_(NULL), current_split_start_ns_(0) {
+    : name_(name), precise_(precise), verbose_(verbose), current_split_(NULL) {
 }
 
 void TimingLogger::Reset() {
   current_split_ = NULL;
-  current_split_start_ns_ = 0;
   splits_.clear();
 }
 
 void TimingLogger::StartSplit(const char* new_split_label) {
-  DCHECK(current_split_ == NULL);
-  if (verbose_) {
-    LOG(INFO) << "Begin: " << new_split_label;
-  }
-  current_split_ = new_split_label;
-  ATRACE_BEGIN(current_split_);
-  current_split_start_ns_ = NanoTime();
+  DCHECK(new_split_label != NULL) << "Starting split (" << new_split_label << ") with null label.";
+  TimingLogger::ScopedSplit* explicit_scoped_split = new TimingLogger::ScopedSplit(new_split_label, this);
+  explicit_scoped_split->explicit_ = true;
+}
+
+void TimingLogger::EndSplit() {
+  CHECK(current_split_ != NULL) << "Ending a non-existent split.";
+  DCHECK(current_split_->label_ != NULL);
+  DCHECK(current_split_->explicit_ == true) << "Explicitly ending scoped split: " << current_split_->label_;
+
+  delete current_split_;
 }
 
 // Ends the current split and starts the one given by the label.
 void TimingLogger::NewSplit(const char* new_split_label) {
-  DCHECK(current_split_ != NULL);
-  uint64_t current_time = NanoTime();
-  uint64_t split_time = current_time - current_split_start_ns_;
-  ATRACE_END();
-  splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_));
-  if (verbose_) {
-    LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time) << "\n"
-        << "Begin: " << new_split_label;
-  }
-  current_split_ = new_split_label;
-  ATRACE_BEGIN(current_split_);
-  current_split_start_ns_ = current_time;
-}
+  CHECK(current_split_ != NULL) << "Inserting a new split (" << new_split_label
+                                << ") into a non-existent split.";
+  DCHECK(new_split_label != NULL) << "New split (" << new_split_label << ") with null label.";
 
-void TimingLogger::EndSplit() {
-  DCHECK(current_split_ != NULL);
-  uint64_t current_time = NanoTime();
-  uint64_t split_time = current_time - current_split_start_ns_;
-  ATRACE_END();
-  if (verbose_) {
-    LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time);
-  }
-  splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_));
+  current_split_->TailInsertSplit(new_split_label);
 }
 
 uint64_t TimingLogger::GetTotalNs() const {
   uint64_t total_ns = 0;
-  typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It;
-  for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) {
-    std::pair<uint64_t, const char*> split = *it;
+  for (base::TimingLogger::SplitsIterator it = splits_.begin(), end = splits_.end();
+       it != end; ++it) {
+    base::TimingLogger::SplitTiming split = *it;
     total_ns += split.first;
   }
   return total_ns;
@@ -199,9 +166,9 @@ uint64_t TimingLogger::GetTotalNs() const {
 void TimingLogger::Dump(std::ostream &os) const {
   uint64_t longest_split = 0;
   uint64_t total_ns = 0;
-  typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It;
-  for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) {
-    std::pair<uint64_t, const char*> split = *it;
+  for (base::TimingLogger::SplitsIterator it = splits_.begin(), end = splits_.end();
+       it != end; ++it) {
+    base::TimingLogger::SplitTiming split = *it;
     uint64_t split_time = split.first;
     longest_split = std::max(longest_split, split_time);
     total_ns += split_time;
@@ -210,8 +177,9 @@ void TimingLogger::Dump(std::ostream &os) const {
   TimeUnit tu = GetAppropriateTimeUnit(longest_split);
   uint64_t divisor = GetNsToTimeUnitDivisor(tu);
   // Print formatted splits.
-  for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) {
-    std::pair<uint64_t, const char*> split = *it;
+  for (base::TimingLogger::SplitsIterator it = splits_.begin(), end = splits_.end();
+       it != end; ++it) {
+    base::TimingLogger::SplitTiming split = *it;
     uint64_t split_time = split.first;
     if (!precise_ && divisor >= 1000) {
       // Make the fractional part 0.
@@ -223,5 +191,102 @@ void TimingLogger::Dump(std::ostream &os) const {
   os << name_ << ": end, " << NsToMs(total_ns) << " ms\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 explcitly 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_->UnPause();
+  }
+}
+
+
+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;
+  }
+
+  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::UnPause() {
+  uint64_t current_time = NanoTime();
+
+  start_ns_ = current_time;
+  ATRACE_BEGIN(label_);
+}
+
 }  // namespace base
 }  // namespace art
diff --git a/runtime/base/timing_logger.h b/runtime/base/timing_logger.h
index 0998837517..8649a960a2 100644
--- a/runtime/base/timing_logger.h
+++ b/runtime/base/timing_logger.h
@@ -23,6 +23,7 @@
 
 #include <string>
 #include <vector>
+#include <map>
 
 namespace art {
 
@@ -32,6 +33,9 @@ namespace base {
 
 class CumulativeLogger {
  public:
+  typedef std::map<std::string, Histogram<uint64_t> *> Histograms;
+  typedef std::map<std::string, Histogram<uint64_t> *>::const_iterator HistogramsIterator;
+
   explicit CumulativeLogger(const std::string& name);
   void prepare_stats();
   ~CumulativeLogger();
@@ -51,11 +55,10 @@ class CumulativeLogger {
   void DumpHistogram(std::ostream &os) EXCLUSIVE_LOCKS_REQUIRED(lock_);
   uint64_t GetTotalTime() const;
   static const uint64_t kAdjust = 1000;
-  std::vector<Histogram<uint64_t> *> histograms_ GUARDED_BY(lock_);
+  Histograms histograms_ GUARDED_BY(lock_);
   std::string name_;
   const std::string lock_name_;
   mutable Mutex lock_ DEFAULT_MUTEX_ACQUIRED_AFTER;
-  size_t index_ GUARDED_BY(lock_);
   size_t iterations_ GUARDED_BY(lock_);
 
   DISALLOW_COPY_AND_ASSIGN(CumulativeLogger);
@@ -63,16 +66,22 @@ class CumulativeLogger {
 
 namespace base {
 
-// A replacement to timing logger that know when a split starts for the purposes of logging.
+
+// 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;
+  typedef std::vector<SplitTiming>::const_iterator SplitsIterator;
+
   explicit TimingLogger(const char* name, bool precise, bool verbose);
 
   // Clears current splits and labels.
   void Reset();
 
-  // Starts a split, a split shouldn't be in progress.
-  void StartSplit(const char*  new_split_label);
+  // Starts a split
+  void StartSplit(const char* new_split_label);
 
   // Ends the current split and starts the one given by the label.
   void NewSplit(const char* new_split_label);
@@ -84,10 +93,53 @@ class TimingLogger {
 
   void Dump(std::ostream& os) const;
 
-  const std::vector<std::pair<uint64_t, const char*> >& GetSplits() 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();
+
+      // Unpauses timing of the split, usually because a nested split has ended.
+      void UnPause();
+
+      // 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_;
+
+      DISALLOW_COPY_AND_ASSIGN(ScopedSplit);
+  };
+
+  const SplitTimings& GetSplits() const {
     return splits_;
   }
 
+  friend class ScopedSplit;
  protected:
   // The name of the timing logger.
   const char* name_;
@@ -99,14 +151,11 @@ class TimingLogger {
   // Verbose logging.
   const bool verbose_;
 
-  // The name of the current split.
-  const char* current_split_;
+  // The current scoped split is also the 'top' of the stack of splits in progress.
+  ScopedSplit* current_split_;
 
-  // The nanosecond time the current split started on.
-  uint64_t current_split_start_ns_;
-
-  // Splits are nanosecond times and split names.
-  std::vector<std::pair<uint64_t, const char*> > splits_;
+  // Splits that have ended.
+  SplitTimings splits_;
 
  private:
   DISALLOW_COPY_AND_ASSIGN(TimingLogger);
diff --git a/runtime/base/timing_logger_test.cc b/runtime/base/timing_logger_test.cc
new file mode 100644
index 0000000000..8f28e4809b
--- /dev/null
+++ b/runtime/base/timing_logger_test.cc
@@ -0,0 +1,160 @@
+/*
+ * Copyright (C) 2012 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "timing_logger.h"
+
+#include "common_test.h"
+
+namespace art {
+
+class TimingLoggerTest : public CommonTest {};
+
+// TODO: Negative test cases (improper pairing of EndSplit, etc.)
+
+TEST_F(TimingLoggerTest, StartEnd) {
+  const char* split1name = "First Split";
+  base::TimingLogger timings("StartEnd", true, false);
+
+  timings.StartSplit(split1name);
+
+  timings.EndSplit();  // Ends split1.
+
+  const base::TimingLogger::SplitTimings& splits = timings.GetSplits();
+
+  EXPECT_EQ(1U, splits.size());
+  EXPECT_STREQ(splits[0].second, split1name);
+}
+
+
+TEST_F(TimingLoggerTest, StartNewEnd) {
+  const char* split1name = "First Split";
+  const char* split2name = "Second Split";
+  const char* split3name = "Third Split";
+  base::TimingLogger timings("StartNewEnd", true, false);
+
+  timings.StartSplit(split1name);
+
+  timings.NewSplit(split2name);  // Ends split1.
+
+  timings.NewSplit(split3name);  // Ends split2.
+
+  timings.EndSplit();  // Ends split3.
+
+  const base::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);
+}
+
+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";
+  base::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 base::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);
+}
+
+
+TEST_F(TimingLoggerTest, Scoped) {
+  const char* outersplit = "Outer Split";
+  const char* innersplit1 = "Inner Split 1";
+  const char* innerinnersplit1 = "Inner Inner Split 1";
+  const char* innersplit2 = "Inner Split 2";
+  base::TimingLogger timings("Scoped", true, false);
+
+  {
+      base::TimingLogger::ScopedSplit outer(outersplit, &timings);
+
+      {
+          base::TimingLogger::ScopedSplit inner1(innersplit1, &timings);
+
+          {
+              base::TimingLogger::ScopedSplit innerinner1(innerinnersplit1, &timings);
+          }  // Ends innerinnersplit1.
+      }  // Ends innersplit1.
+
+      {
+          base::TimingLogger::ScopedSplit inner2(innersplit2, &timings);
+      }  // Ends innersplit2.
+  }  // Ends outersplit.
+
+  const base::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);
+}
+
+
+TEST_F(TimingLoggerTest, ScopedAndExplicit) {
+  const char* outersplit = "Outer Split";
+  const char* innersplit = "Inner Split";
+  const char* innerinnersplit1 = "Inner Inner Split 1";
+  const char* innerinnersplit2 = "Inner Inner Split 2";
+  base::TimingLogger timings("Scoped", true, false);
+
+  timings.StartSplit(outersplit);
+
+  {
+      base::TimingLogger::ScopedSplit inner(innersplit, &timings);
+
+      timings.StartSplit(innerinnersplit1);
+
+      timings.NewSplit(innerinnersplit2);  // Ends innerinnersplit1.
+  }  // Ends innerinnersplit2, then innersplit.
+
+  timings.EndSplit();  // Ends outersplit.
+
+  const base::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);
+}
+
+}  // namespace art
diff --git a/runtime/gc/collector/mark_sweep.cc b/runtime/gc/collector/mark_sweep.cc
index 8a08f0893a..d4970e71f4 100644
--- a/runtime/gc/collector/mark_sweep.cc
+++ b/runtime/gc/collector/mark_sweep.cc
@@ -107,6 +107,7 @@ void MarkSweep::ImmuneSpace(space::ContinuousSpace* space) {
 }
 
 void MarkSweep::BindBitmaps() {
+  timings_.StartSplit("BindBitmaps");
   const std::vector<space::ContinuousSpace*>& spaces = GetHeap()->GetContinuousSpaces();
   WriterMutexLock mu(Thread::Current(), *Locks::heap_bitmap_lock_);
 
@@ -118,6 +119,7 @@ void MarkSweep::BindBitmaps() {
       ImmuneSpace(space);
     }
   }
+  timings_.EndSplit();
 }
 
 MarkSweep::MarkSweep(Heap* heap, bool is_concurrent, const std::string& name_prefix)
@@ -166,13 +168,17 @@ void MarkSweep::InitializePhase() {
   reference_count_ = 0;
   java_lang_Class_ = Class::GetJavaLangClass();
   CHECK(java_lang_Class_ != NULL);
+  timings_.EndSplit();
+
   FindDefaultMarkBitmap();
-  // Do any pre GC verification.
+
+// Do any pre GC verification.
+  timings_.StartSplit("PreGcVerification");
   heap_->PreGcVerification(this);
+  timings_.EndSplit();
 }
 
 void MarkSweep::ProcessReferences(Thread* self) {
-  timings_.NewSplit("ProcessReferences");
   WriterMutexLock mu(self, *Locks::heap_bitmap_lock_);
   ProcessReferences(&soft_reference_list_, clear_soft_references_, &weak_reference_list_,
                     &finalizer_reference_list_, &phantom_reference_list_);
@@ -184,7 +190,6 @@ bool MarkSweep::HandleDirtyObjectsPhase() {
   Locks::mutator_lock_->AssertExclusiveHeld(self);
 
   {
-    timings_.NewSplit("ReMarkRoots");
     WriterMutexLock mu(self, *Locks::heap_bitmap_lock_);
 
     // Re-mark root set.
@@ -214,29 +219,26 @@ void MarkSweep::MarkingPhase() {
   Heap* heap = GetHeap();
   Thread* self = Thread::Current();
 
-  timings_.NewSplit("BindBitmaps");
   BindBitmaps();
   FindDefaultMarkBitmap();
+
   // Process dirty cards and add dirty cards to mod union tables.
   heap->ProcessCards(timings_);
 
   // Need to do this before the checkpoint since we don't want any threads to add references to
   // the live stack during the recursive mark.
-  timings_.NewSplit("SwapStacks");
+  timings_.StartSplit("SwapStacks");
   heap->SwapStacks();
+  timings_.EndSplit();
 
   WriterMutexLock mu(self, *Locks::heap_bitmap_lock_);
   if (Locks::mutator_lock_->IsExclusiveHeld(self)) {
     // If we exclusively hold the mutator lock, all threads must be suspended.
-    timings_.NewSplit("MarkRoots");
     MarkRoots();
   } else {
-    timings_.NewSplit("MarkRootsCheckpoint");
     MarkRootsCheckpoint(self);
-    timings_.NewSplit("MarkNonThreadRoots");
     MarkNonThreadRoots();
   }
-  timings_.NewSplit("MarkConcurrentRoots");
   MarkConcurrentRoots();
 
   heap->UpdateAndMarkModUnion(this, timings_, GetGcType());
@@ -246,12 +248,13 @@ void MarkSweep::MarkingPhase() {
 void MarkSweep::MarkReachableObjects() {
   // Mark everything allocated since the last as GC live so that we can sweep concurrently,
   // knowing that new allocations won't be marked as live.
-  timings_.NewSplit("MarkStackAsLive");
+  timings_.StartSplit("MarkStackAsLive");
   accounting::ObjectStack* live_stack = heap_->GetLiveStack();
   heap_->MarkAllocStack(heap_->alloc_space_->GetLiveBitmap(),
                        heap_->large_object_space_->GetLiveObjects(),
                        live_stack);
   live_stack->Reset();
+  timings_.EndSplit();
   // Recursively mark all the non-image bits set in the mark bitmap.
   RecursiveMark();
 }
@@ -288,7 +291,9 @@ void MarkSweep::ReclaimPhase() {
     ReaderMutexLock mu(self, *Locks::heap_bitmap_lock_);
     VerifyImageRoots();
   }
+  timings_.StartSplit("PreSweepingGcVerification");
   heap_->PreSweepingGcVerification(this);
+  timings_.EndSplit();
 
   {
     WriterMutexLock mu(self, *Locks::heap_bitmap_lock_);
@@ -299,8 +304,9 @@ void MarkSweep::ReclaimPhase() {
     // Swap the live and mark bitmaps for each space which we modified space. This is an
     // optimization that enables us to not clear live bits inside of the sweep. Only swaps unbound
     // bitmaps.
-    timings_.NewSplit("SwapBitmaps");
+    timings_.StartSplit("SwapBitmaps");
     SwapBitmaps();
+    timings_.EndSplit();
 
     // Unbind the live and mark bitmaps.
     UnBindBitmaps();
@@ -313,6 +319,7 @@ void MarkSweep::SetImmuneRange(Object* begin, Object* end) {
 }
 
 void MarkSweep::FindDefaultMarkBitmap() {
+  timings_.StartSplit("FindDefaultMarkBitmap");
   const std::vector<space::ContinuousSpace*>& spaces = GetHeap()->GetContinuousSpaces();
   // TODO: C++0x
   typedef std::vector<space::ContinuousSpace*>::const_iterator It;
@@ -321,6 +328,7 @@ void MarkSweep::FindDefaultMarkBitmap() {
     if (space->GetGcRetentionPolicy() == space::kGcRetentionPolicyAlwaysCollect) {
       current_mark_bitmap_ = (*it)->GetMarkBitmap();
       CHECK(current_mark_bitmap_ != NULL);
+      timings_.EndSplit();
       return;
     }
   }
@@ -522,16 +530,22 @@ void MarkSweep::VerifyRoots() {
 
 // Marks all objects in the root set.
 void MarkSweep::MarkRoots() {
+  timings_.StartSplit("MarkRoots");
   Runtime::Current()->VisitNonConcurrentRoots(MarkObjectCallback, this);
+  timings_.EndSplit();
 }
 
 void MarkSweep::MarkNonThreadRoots() {
+  timings_.StartSplit("MarkNonThreadRoots");
   Runtime::Current()->VisitNonThreadRoots(MarkObjectCallback, this);
+  timings_.EndSplit();
 }
 
 void MarkSweep::MarkConcurrentRoots() {
+  timings_.StartSplit("MarkConcurrentRoots");
   // Visit all runtime roots and clear dirty flags.
   Runtime::Current()->VisitConcurrentRoots(MarkObjectCallback, this, false, true);
+  timings_.EndSplit();
 }
 
 class CheckObjectVisitor {
@@ -601,13 +615,13 @@ void MarkSweep::ScanGrayObjects(byte minimum_age) {
     space::ContinuousSpace* space = *it;
     switch (space->GetGcRetentionPolicy()) {
       case space::kGcRetentionPolicyNeverCollect:
-        timings_.NewSplit("ScanGrayImageSpaceObjects");
+        timings_.StartSplit("ScanGrayImageSpaceObjects");
         break;
       case space::kGcRetentionPolicyFullCollect:
-        timings_.NewSplit("ScanGrayZygoteSpaceObjects");
+        timings_.StartSplit("ScanGrayZygoteSpaceObjects");
         break;
       case space::kGcRetentionPolicyAlwaysCollect:
-        timings_.NewSplit("ScanGrayAllocSpaceObjects");
+        timings_.StartSplit("ScanGrayAllocSpaceObjects");
         break;
     }
     byte* begin = space->Begin();
@@ -615,6 +629,7 @@ void MarkSweep::ScanGrayObjects(byte minimum_age) {
     // Image spaces are handled properly since live == marked for them.
     accounting::SpaceBitmap* mark_bitmap = space->GetMarkBitmap();
     card_table->Scan(mark_bitmap, begin, end, visitor, minimum_age);
+    timings_.EndSplit();
   }
 }
 
@@ -638,6 +653,7 @@ void MarkSweep::VerifyImageRoots() {
   // Verify roots ensures that all the references inside the image space point
   // objects which are either in the image space or marked objects in the alloc
   // space
+  timings_.StartSplit("VerifyImageRoots");
   CheckBitmapVisitor visitor(this);
   const std::vector<space::ContinuousSpace*>& spaces = GetHeap()->GetContinuousSpaces();
   // TODO: C++0x
@@ -652,12 +668,13 @@ void MarkSweep::VerifyImageRoots() {
       live_bitmap->VisitMarkedRange(begin, end, visitor);
     }
   }
+  timings_.EndSplit();
 }
 
 // Populates the mark stack based on the set of marked objects and
 // recursively marks until the mark stack is emptied.
 void MarkSweep::RecursiveMark() {
-  timings_.NewSplit("RecursiveMark");
+  base::TimingLogger::ScopedSplit("RecursiveMark", &timings_);
   // RecursiveMark will build the lists of known instances of the Reference classes.
   // See DelayReferenceReferent for details.
   CHECK(soft_reference_list_ == NULL);
@@ -688,7 +705,6 @@ void MarkSweep::RecursiveMark() {
       }
     }
   }
-  timings_.NewSplit("ProcessMarkStack");
   ProcessMarkStack();
 }
 
@@ -700,12 +716,13 @@ bool MarkSweep::IsMarkedCallback(const Object* object, void* arg) {
 
 void MarkSweep::RecursiveMarkDirtyObjects(byte minimum_age) {
   ScanGrayObjects(minimum_age);
-  timings_.NewSplit("ProcessMarkStack");
   ProcessMarkStack();
 }
 
 void MarkSweep::ReMarkRoots() {
+  timings_.StartSplit("ReMarkRoots");
   Runtime::Current()->VisitRoots(ReMarkObjectVisitor, this, true, true);
+  timings_.EndSplit();
 }
 
 void MarkSweep::SweepJniWeakGlobals(IsMarkedTester is_marked, void* arg) {
@@ -744,12 +761,14 @@ void MarkSweep::SweepSystemWeaksArray(accounting::ObjectStack* allocations) {
   // So compute !(!IsMarked && IsLive) which is equal to (IsMarked || !IsLive).
   // Or for swapped (IsLive || !IsMarked).
 
+  timings_.StartSplit("SweepSystemWeaksArray");
   ArrayMarkedCheck visitor;
   visitor.live_stack = allocations;
   visitor.mark_sweep = this;
   runtime->GetInternTable()->SweepInternTableWeaks(IsMarkedArrayCallback, &visitor);
   runtime->GetMonitorList()->SweepMonitorList(IsMarkedArrayCallback, &visitor);
   SweepJniWeakGlobals(IsMarkedArrayCallback, &visitor);
+  timings_.EndSplit();
 }
 
 void MarkSweep::SweepSystemWeaks() {
@@ -759,9 +778,11 @@ void MarkSweep::SweepSystemWeaks() {
   // !IsMarked && IsLive
   // So compute !(!IsMarked && IsLive) which is equal to (IsMarked || !IsLive).
   // Or for swapped (IsLive || !IsMarked).
+  timings_.StartSplit("SweepSystemWeaks");
   runtime->GetInternTable()->SweepInternTableWeaks(IsMarkedCallback, this);
   runtime->GetMonitorList()->SweepMonitorList(IsMarkedCallback, this);
   SweepJniWeakGlobals(IsMarkedCallback, this);
+  timings_.EndSplit();
 }
 
 bool MarkSweep::VerifyIsLiveCallback(const Object* obj, void* arg) {
@@ -826,6 +847,7 @@ class CheckpointMarkThreadRoots : public Closure {
 
 void MarkSweep::MarkRootsCheckpoint(Thread* self) {
   CheckpointMarkThreadRoots check_point(this);
+  timings_.StartSplit("MarkRootsCheckpoint");
   ThreadList* thread_list = Runtime::Current()->GetThreadList();
   // Request the check point is run on all threads returning a count of the threads that must
   // run through the barrier including self.
@@ -840,6 +862,7 @@ void MarkSweep::MarkRootsCheckpoint(Thread* self) {
   self->SetState(kWaitingPerformingGc);
   Locks::mutator_lock_->SharedLock(self);
   Locks::heap_bitmap_lock_->ExclusiveLock(self);
+  timings_.EndSplit();
 }
 
 void MarkSweep::SweepCallback(size_t num_ptrs, Object** ptrs, void* arg) {
@@ -878,10 +901,9 @@ void MarkSweep::SweepArray(accounting::ObjectStack* allocations, bool swap_bitma
 
   // If we don't swap bitmaps then newly allocated Weaks go into the live bitmap but not mark
   // bitmap, resulting in occasional frees of Weaks which are still in use.
-  timings_.NewSplit("SweepSystemWeaks");
   SweepSystemWeaksArray(allocations);
 
-  timings_.NewSplit("Process allocation stack");
+  timings_.StartSplit("Process allocation stack");
   // Newly allocated objects MUST be in the alloc space and those are the only objects which we are
   // going to free.
   accounting::SpaceBitmap* live_bitmap = space->GetLiveBitmap();
@@ -915,8 +937,9 @@ void MarkSweep::SweepArray(accounting::ObjectStack* allocations, bool swap_bitma
     }
   }
   CHECK_EQ(count, allocations->Size());
-  timings_.NewSplit("FreeList");
+  timings_.EndSplit();
 
+  timings_.StartSplit("FreeList");
   size_t freed_objects = out - objects;
   freed_bytes += space->FreeList(self, freed_objects, objects);
   VLOG(heap) << "Freed " << freed_objects << "/" << count
@@ -924,9 +947,11 @@ void MarkSweep::SweepArray(accounting::ObjectStack* allocations, bool swap_bitma
   heap_->RecordFree(freed_objects + freed_large_objects, freed_bytes);
   freed_objects_.fetch_add(freed_objects);
   freed_bytes_.fetch_add(freed_bytes);
+  timings_.EndSplit();
 
-  timings_.NewSplit("ResetStack");
+  timings_.StartSplit("ResetStack");
   allocations->Reset();
+  timings_.EndSplit();
 }
 
 void MarkSweep::Sweep(bool swap_bitmaps) {
@@ -934,7 +959,6 @@ void MarkSweep::Sweep(bool swap_bitmaps) {
 
   // If we don't swap bitmaps then newly allocated Weaks go into the live bitmap but not mark
   // bitmap, resulting in occasional frees of Weaks which are still in use.
-  timings_.NewSplit("SweepSystemWeaks");
   SweepSystemWeaks();
 
   const bool partial = (GetGcType() == kGcTypePartial);
@@ -962,22 +986,25 @@ void MarkSweep::Sweep(bool swap_bitmaps) {
         std::swap(live_bitmap, mark_bitmap);
       }
       if (!space->IsZygoteSpace()) {
-        timings_.NewSplit("SweepAllocSpace");
+        timings_.StartSplit("SweepAllocSpace");
         // Bitmaps are pre-swapped for optimization which enables sweeping with the heap unlocked.
         accounting::SpaceBitmap::SweepWalk(*live_bitmap, *mark_bitmap, begin, end,
                                            &SweepCallback, reinterpret_cast<void*>(&scc));
+        timings_.EndSplit();
       } else {
-        timings_.NewSplit("SweepZygote");
+        timings_.StartSplit("SweepZygote");
         // Zygote sweep takes care of dirtying cards and clearing live bits, does not free actual
         // memory.
         accounting::SpaceBitmap::SweepWalk(*live_bitmap, *mark_bitmap, begin, end,
                                            &ZygoteSweepCallback, reinterpret_cast<void*>(&scc));
+        timings_.EndSplit();
       }
     }
   }
 
-  timings_.NewSplit("SweepLargeObjects");
+  timings_.StartSplit("SweepLargeObjects");
   SweepLargeObjects(swap_bitmaps);
+  timings_.EndSplit();
 }
 
 void MarkSweep::SweepLargeObjects(bool swap_bitmaps) {
@@ -1269,8 +1296,10 @@ void MarkSweep::ProcessMarkStackParallel() {
 // Scan anything that's on the mark stack.
 void MarkSweep::ProcessMarkStack() {
   ThreadPool* thread_pool = GetHeap()->GetThreadPool();
+  timings_.StartSplit("ProcessMarkStack");
   if (kParallelMarkStack && thread_pool != NULL && thread_pool->GetThreadCount() > 0) {
     ProcessMarkStackParallel();
+    timings_.EndSplit();
     return;
   }
 
@@ -1312,6 +1341,7 @@ void MarkSweep::ProcessMarkStack() {
       ScanObject(obj);
     }
   }
+  timings_.EndSplit();
 }
 
 // Walks the reference list marking any references subject to the
@@ -1325,6 +1355,7 @@ void MarkSweep::PreserveSomeSoftReferences(Object** list) {
 
   DCHECK(mark_stack_->IsEmpty());
 
+  timings_.StartSplit("PreserveSomeSoftReferences");
   while (*list != NULL) {
     Object* ref = heap_->DequeuePendingReference(list);
     Object* referent = heap_->GetReferenceReferent(ref);
@@ -1344,6 +1375,8 @@ void MarkSweep::PreserveSomeSoftReferences(Object** list) {
     }
   }
   *list = clear;
+  timings_.EndSplit();
+
   // Restart the mark with the newly black references added to the
   // root set.
   ProcessMarkStack();
@@ -1386,6 +1419,7 @@ void MarkSweep::ClearWhiteReferences(Object** list) {
 // referent field is cleared.
 void MarkSweep::EnqueueFinalizerReferences(Object** list) {
   DCHECK(list != NULL);
+  timings_.StartSplit("EnqueueFinalizerReferences");
   MemberOffset zombie_offset = heap_->GetFinalizerReferenceZombieOffset();
   bool has_enqueued = false;
   while (*list != NULL) {
@@ -1401,6 +1435,7 @@ void MarkSweep::EnqueueFinalizerReferences(Object** list) {
       has_enqueued = true;
     }
   }
+  timings_.EndSplit();
   if (has_enqueued) {
     ProcessMarkStack();
   }
@@ -1423,15 +1458,18 @@ void MarkSweep::ProcessReferences(Object** soft_references, bool clear_soft,
     PreserveSomeSoftReferences(soft_references);
   }
 
+  timings_.StartSplit("ProcessReferences");
   // Clear all remaining soft and weak references with white
   // referents.
   ClearWhiteReferences(soft_references);
   ClearWhiteReferences(weak_references);
+  timings_.EndSplit();
 
   // Preserve all white objects with finalize methods and schedule
   // them for finalization.
   EnqueueFinalizerReferences(finalizer_references);
 
+  timings_.StartSplit("ProcessReferences");
   // Clear all f-reachable soft and weak references with white
   // referents.
   ClearWhiteReferences(soft_references);
@@ -1445,9 +1483,11 @@ void MarkSweep::ProcessReferences(Object** soft_references, bool clear_soft,
   DCHECK(*weak_references == NULL);
   DCHECK(*finalizer_references == NULL);
   DCHECK(*phantom_references == NULL);
+  timings_.EndSplit();
 }
 
 void MarkSweep::UnBindBitmaps() {
+  timings_.StartSplit("UnBindBitmaps");
   const std::vector<space::ContinuousSpace*>& spaces = GetHeap()->GetContinuousSpaces();
   // TODO: C++0x
   typedef std::vector<space::ContinuousSpace*>::const_iterator It;
@@ -1465,6 +1505,7 @@ void MarkSweep::UnBindBitmaps() {
       }
     }
   }
+  timings_.EndSplit();
 }
 
 void MarkSweep::FinishPhase() {
@@ -1475,11 +1516,13 @@ void MarkSweep::FinishPhase() {
 
   heap->PostGcVerification(this);
 
-  timings_.NewSplit("GrowForUtilization");
+  timings_.StartSplit("GrowForUtilization");
   heap->GrowForUtilization(GetGcType(), GetDurationNs());
+  timings_.EndSplit();
 
-  timings_.NewSplit("RequestHeapTrim");
+  timings_.StartSplit("RequestHeapTrim");
   heap->RequestHeapTrim();
+  timings_.EndSplit();
 
   // Update the cumulative statistics
   total_time_ns_ += GetDurationNs();
diff --git a/runtime/gc/collector/sticky_mark_sweep.cc b/runtime/gc/collector/sticky_mark_sweep.cc
index 5505336478..aad7c2973f 100644
--- a/runtime/gc/collector/sticky_mark_sweep.cc
+++ b/runtime/gc/collector/sticky_mark_sweep.cc
@@ -55,7 +55,6 @@ void StickyMarkSweep::MarkReachableObjects() {
 }
 
 void StickyMarkSweep::Sweep(bool swap_bitmaps) {
-  timings_.NewSplit("SweepArray");
   accounting::ObjectStack* live_stack = GetHeap()->GetLiveStack();
   SweepArray(live_stack, false);
 }
diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc
index 147ded3c3c..6dcdab9b60 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -1175,17 +1175,6 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus
                                                bool clear_soft_references) {
   Thread* self = Thread::Current();
 
-  switch (gc_cause) {
-    case kGcCauseForAlloc:
-      ATRACE_BEGIN("GC (alloc)");
-      break;
-    case kGcCauseBackground:
-      ATRACE_BEGIN("GC (background)");
-      break;
-    case kGcCauseExplicit:
-      ATRACE_BEGIN("GC (explicit)");
-      break;
-  }
 
   ScopedThreadStateChange tsc(self, kWaitingPerformingGc);
   Locks::mutator_lock_->AssertNotHeld(self);
@@ -1205,7 +1194,9 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus
       }
     }
     if (!start_collect) {
+      // TODO: timinglog this.
       WaitForConcurrentGcToComplete(self);
+
       // TODO: if another thread beat this one to do the GC, perhaps we should just return here?
       //       Not doing at the moment to ensure soft references are cleared.
     }
@@ -1234,6 +1225,18 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus
     gc_type = collector::kGcTypePartial;
   }
 
+  switch (gc_cause) {
+    case kGcCauseForAlloc:
+      ATRACE_BEGIN("GC (alloc)");
+      break;
+    case kGcCauseBackground:
+      ATRACE_BEGIN("GC (background)");
+      break;
+    case kGcCauseExplicit:
+      ATRACE_BEGIN("GC (explicit)");
+      break;
+  }
+
   DCHECK_LT(gc_type, collector::kGcTypeMax);
   DCHECK_NE(gc_type, collector::kGcTypeNone);
   collector::MarkSweep* collector = NULL;
@@ -1249,6 +1252,9 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus
   CHECK(collector != NULL)
       << "Could not find garbage collector with concurrent=" << concurrent_gc_
       << " and type=" << gc_type;
+
+  base::TimingLogger& timings = collector->GetTimings();
+
   collector->clear_soft_references_ = clear_soft_references;
   collector->Run();
   total_objects_freed_ever_ += collector->GetFreedObjects();
@@ -1257,42 +1263,43 @@ collector::GcType Heap::CollectGarbageInternal(collector::GcType gc_type, GcCaus
   const size_t duration = collector->GetDurationNs();
   std::vector<uint64_t> pauses = collector->GetPauseTimes();
   bool was_slow = duration > kSlowGcThreshold ||
-      (gc_cause == kGcCauseForAlloc && duration > kLongGcPauseThreshold);
+          (gc_cause == kGcCauseForAlloc && duration > kLongGcPauseThreshold);
   for (size_t i = 0; i < pauses.size(); ++i) {
-    if (pauses[i] > kLongGcPauseThreshold) {
-      was_slow = true;
-    }
+      if (pauses[i] > kLongGcPauseThreshold) {
+          was_slow = true;
+      }
   }
 
   if (was_slow) {
-    const size_t percent_free = GetPercentFree();
-    const size_t current_heap_size = GetBytesAllocated();
-    const size_t total_memory = GetTotalMemory();
-    std::ostringstream pause_string;
-    for (size_t i = 0; i < pauses.size(); ++i) {
-      pause_string << PrettyDuration((pauses[i] / 1000) * 1000)
-                   << ((i != pauses.size() - 1) ? ", " : "");
-    }
-    LOG(INFO) << gc_cause << " " << collector->GetName()
-              << "GC freed " << PrettySize(collector->GetFreedBytes()) << ", "
-              << percent_free << "% free, " << PrettySize(current_heap_size) << "/"
-              << PrettySize(total_memory) << ", " << "paused " << pause_string.str()
-              << " total " << PrettyDuration((duration / 1000) * 1000);
-    if (VLOG_IS_ON(heap)) {
-      LOG(INFO) << Dumpable<base::TimingLogger>(collector->GetTimings());
-    }
+      const size_t percent_free = GetPercentFree();
+      const size_t current_heap_size = GetBytesAllocated();
+      const size_t total_memory = GetTotalMemory();
+      std::ostringstream pause_string;
+      for (size_t i = 0; i < pauses.size(); ++i) {
+          pause_string << PrettyDuration((pauses[i] / 1000) * 1000)
+                       << ((i != pauses.size() - 1) ? ", " : "");
+      }
+      LOG(INFO) << gc_cause << " " << collector->GetName()
+                << "GC freed " << PrettySize(collector->GetFreedBytes()) << ", "
+                << percent_free << "% free, " << PrettySize(current_heap_size) << "/"
+                << PrettySize(total_memory) << ", " << "paused " << pause_string.str()
+                << " total " << PrettyDuration((duration / 1000) * 1000);
+      if (VLOG_IS_ON(heap)) {
+          LOG(INFO) << Dumpable<base::TimingLogger>(timings);
+      }
   }
 
   {
-    MutexLock mu(self, *gc_complete_lock_);
-    is_gc_running_ = false;
-    last_gc_type_ = gc_type;
-    // Wake anyone who may have been waiting for the GC to complete.
-    gc_complete_cond_->Broadcast(self);
+      MutexLock mu(self, *gc_complete_lock_);
+      is_gc_running_ = false;
+      last_gc_type_ = gc_type;
+      // Wake anyone who may have been waiting for the GC to complete.
+      gc_complete_cond_->Broadcast(self);
   }
 
-  // Inform DDMS that a GC completed.
   ATRACE_END();
+
+  // Inform DDMS that a GC completed.
   Dbg::GcDidFinish();
   return gc_type;
 }
@@ -1305,9 +1312,10 @@ void Heap::UpdateAndMarkModUnion(collector::MarkSweep* mark_sweep, base::TimingL
     return;
   }
 
+  base::TimingLogger::ScopedSplit split("UpdateModUnionTable", &timings);
   // Update zygote mod union table.
   if (gc_type == collector::kGcTypePartial) {
-    timings.NewSplit("UpdateZygoteModUnionTable");
+    base::TimingLogger::ScopedSplit split("UpdateZygoteModUnionTable", &timings);
     zygote_mod_union_table_->Update();
 
     timings.NewSplit("ZygoteMarkReferences");
@@ -1594,15 +1602,15 @@ void Heap::ProcessCards(base::TimingLogger& timings) {
   for (It it = continuous_spaces_.begin(), end = continuous_spaces_.end(); it != end; ++it) {
     space::ContinuousSpace* space = *it;
     if (space->IsImageSpace()) {
-      timings.NewSplit("ModUnionClearCards");
+      base::TimingLogger::ScopedSplit split("ImageModUnionClearCards", &timings);
       image_mod_union_table_->ClearCards(space);
     } else if (space->IsZygoteSpace()) {
-      timings.NewSplit("ZygoteModUnionClearCards");
+      base::TimingLogger::ScopedSplit split("ZygoteModUnionClearCards", &timings);
       zygote_mod_union_table_->ClearCards(space);
     } else {
+      base::TimingLogger::ScopedSplit split("AllocSpaceClearCards", &timings);
       // No mod union table for the AllocSpace. Age the cards so that the GC knows that these cards
       // were dirty before the GC started.
-      timings.NewSplit("AllocSpaceClearCards");
       card_table_->ModifyCardsAtomic(space->Begin(), space->End(), AgeCardVisitor(), VoidFunctor());
     }
   }