Add systrace support to NewTimingLogger, migrate compiler timing logging to NewTimingLogger

Rpleaced old TimingLogger by NewTimingLogger, renamed NewTimingLogger to TimingLogger, added systrace support to TimingLogger.
Tests passing, phone booting, systrace working.

Change-Id: I2aeffb8bcb7f0fd979d8a2a3a8bcfbaa02413679

2 files changed, 24 insertions, 88 deletions

diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc
index bf6fd17..dfb0220 100644
--- a/runtime/base/timing_logger.cc
+++ b/runtime/base/timing_logger.cc
@@ -14,6 +14,11 @@
  * limitations under the License.
  */
 
+
+#define ATRACE_TAG ATRACE_TAG_DALVIK
+#include <stdio.h>
+#include <cutils/trace.h>
+
 #include "timing_logger.h"
 
 #include "base/logging.h"
@@ -26,49 +31,6 @@
 
 namespace art {
 
-void TimingLogger::Reset() {
-  times_.clear();
-  labels_.clear();
-  AddSplit("");
-}
-
-TimingLogger::TimingLogger(const std::string &name, bool precise)
-    : name_(name),
-      precise_(precise) {
-  AddSplit("");
-}
-
-void TimingLogger::AddSplit(const std::string &label) {
-  times_.push_back(NanoTime());
-  labels_.push_back(label);
-}
-
-uint64_t TimingLogger::GetTotalNs() const {
-  return times_.back() - times_.front();
-}
-
-void TimingLogger::Dump(std::ostream &os) const {
-  uint64_t largest_time = 0;
-  os << name_ << ": begin\n";
-  for (size_t i = 1; i < times_.size(); ++i) {
-    uint64_t delta_time = times_[i] - times_[i - 1];
-    largest_time = std::max(largest_time, delta_time);
-  }
-  // Compute which type of unit we will use for printing the timings.
-  TimeUnit tu = GetAppropriateTimeUnit(largest_time);
-  uint64_t divisor = GetNsToTimeUnitDivisor(tu);
-  for (size_t i = 1; i < times_.size(); ++i) {
-    uint64_t delta_time = times_[i] - times_[i - 1];
-    if (!precise_ && divisor >= 1000) {
-      // Make the fraction 0.
-      delta_time -= delta_time % (divisor / 1000);
-    }
-    os << name_ << ": " << std::setw(8) << FormatDuration(delta_time, tu) << " "
-       << labels_[i] << "\n";
-  }
-  os << name_ << ": end, " << NsToMs(GetTotalNs()) << " ms\n";
-}
-
 CumulativeLogger::CumulativeLogger(const std::string& name)
     : name_(name),
       lock_name_("CumulativeLoggerLock" + name),
@@ -112,17 +74,8 @@ uint64_t CumulativeLogger::GetTotalTime() const {
   return total;
 }
 
-void CumulativeLogger::AddLogger(const TimingLogger &logger) {
-  MutexLock mu(Thread::Current(), lock_);
-  DCHECK_EQ(logger.times_.size(), logger.labels_.size());
-  for (size_t i = 1; i < logger.times_.size(); ++i) {
-    const uint64_t delta_time = logger.times_[i] - logger.times_[i - 1];
-    const std::string &label = logger.labels_[i];
-    AddPair(label, delta_time);
-  }
-}
 
-void CumulativeLogger::AddNewLogger(const base::NewTimingLogger &logger) {
+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;
@@ -183,51 +136,55 @@ void CumulativeLogger::DumpHistogram(std::ostream &os) {
 
 namespace base {
 
-NewTimingLogger::NewTimingLogger(const char* name, bool precise, bool verbose)
+TimingLogger::TimingLogger(const char* name, bool precise, bool verbose)
     : name_(name), precise_(precise), verbose_(verbose),
       current_split_(NULL), current_split_start_ns_(0) {
 }
 
-void NewTimingLogger::Reset() {
+void TimingLogger::Reset() {
   current_split_ = NULL;
   current_split_start_ns_ = 0;
   splits_.clear();
 }
 
-void NewTimingLogger::StartSplit(const char* new_split_label) {
+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();
 }
 
 // Ends the current split and starts the one given by the label.
-void NewTimingLogger::NewSplit(const char* new_split_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;
 }
 
-void NewTimingLogger::EndSplit() {
+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_));
 }
 
-uint64_t NewTimingLogger::GetTotalNs() const {
+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) {
@@ -237,7 +194,7 @@ uint64_t NewTimingLogger::GetTotalNs() const {
   return total_ns;
 }
 
-void NewTimingLogger::Dump(std::ostream &os) 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;
diff --git a/runtime/base/timing_logger.h b/runtime/base/timing_logger.h
index 0f00a04..0998837 100644
--- a/runtime/base/timing_logger.h
+++ b/runtime/base/timing_logger.h
@@ -26,27 +26,8 @@
 
 namespace art {
 
-class CumulativeLogger;
-
-class TimingLogger {
- public:
-  explicit TimingLogger(const std::string& name, bool precise);
-  void AddSplit(const std::string& label);
-  void Dump(std::ostream& os) const;
-  void Reset();
-  uint64_t GetTotalNs() const;
-
- protected:
-  const std::string name_;
-  const bool precise_;
-  std::vector<uint64_t> times_;
-  std::vector<std::string> labels_;
-
-  friend class CumulativeLogger;
-};
-
 namespace base {
-  class NewTimingLogger;
+  class TimingLogger;
 }  // namespace base
 
 class CumulativeLogger {
@@ -62,8 +43,7 @@ class CumulativeLogger {
   // Allow the name to be modified, particularly when the cumulative logger is a field within a
   // parent class that is unable to determine the "name" of a sub-class.
   void SetName(const std::string& name);
-  void AddLogger(const TimingLogger& logger) LOCKS_EXCLUDED(lock_);
-  void AddNewLogger(const base::NewTimingLogger& logger) LOCKS_EXCLUDED(lock_);
+  void AddLogger(const base::TimingLogger& logger) LOCKS_EXCLUDED(lock_);
 
  private:
   void AddPair(const std::string &label, uint64_t delta_time)
@@ -84,16 +64,15 @@ class CumulativeLogger {
 namespace base {
 
 // A replacement to timing logger that know when a split starts for the purposes of logging.
-// TODO: replace uses of TimingLogger with base::NewTimingLogger.
-class NewTimingLogger {
+class TimingLogger {
  public:
-  explicit NewTimingLogger(const char* name, bool precise, bool verbose);
+  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);
+  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);
@@ -111,7 +90,7 @@ class NewTimingLogger {
 
  protected:
   // The name of the timing logger.
-  const std::string name_;
+  const char* name_;
 
   // Do we want to print the exactly recorded split (true) or round down to the time unit being
   // used (false).
@@ -130,7 +109,7 @@ class NewTimingLogger {
   std::vector<std::pair<uint64_t, const char*> > splits_;
 
  private:
-  DISALLOW_COPY_AND_ASSIGN(NewTimingLogger);
+  DISALLOW_COPY_AND_ASSIGN(TimingLogger);
 };
 
 }  // namespace base