Change JIT timings to collect thread CPU time.

Test: m
Test: timing_logger_test.cc
Change-Id: I26fd86e66c4dd967dc62b629f6b6cde97b71ed13

4 files changed, 48 insertions, 7 deletions

diff --git a/compiler/jit/jit_compiler.cc b/compiler/jit/jit_compiler.cc
index 5fdf9ff07c..511a44af04 100644
--- a/compiler/jit/jit_compiler.cc
+++ b/compiler/jit/jit_compiler.cc
@@ -175,7 +175,8 @@ bool JitCompiler::CompileMethod(Thread* self, ArtMethod* method, bool osr) {
   DCHECK(!method->IsProxyMethod());
   DCHECK(method->GetDeclaringClass()->IsResolved());
 
-  TimingLogger logger("JIT compiler timing logger", true, VLOG_IS_ON(jit));
+  TimingLogger logger(
+      "JIT compiler timing logger", true, VLOG_IS_ON(jit), TimingLogger::TimingKind::kThreadCpu);
   self->AssertNoPendingException();
   Runtime* runtime = Runtime::Current();
 
diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc
index b2e5251e73..b8d6931a83 100644
--- a/runtime/base/timing_logger.cc
+++ b/runtime/base/timing_logger.cc
@@ -128,8 +128,11 @@ void CumulativeLogger::DumpHistogram(std::ostream &os) const {
   os << "Done Dumping histograms\n";
 }
 
-TimingLogger::TimingLogger(const char* name, bool precise, bool verbose)
-    : name_(name), precise_(precise), verbose_(verbose) {
+TimingLogger::TimingLogger(const char* name,
+                           bool precise,
+                           bool verbose,
+                           TimingLogger::TimingKind kind)
+    : name_(name), precise_(precise), verbose_(verbose), kind_(kind) {
 }
 
 void TimingLogger::Reset() {
@@ -138,12 +141,12 @@ void TimingLogger::Reset() {
 
 void TimingLogger::StartTiming(const char* label) {
   DCHECK(label != nullptr);
-  timings_.push_back(Timing(NanoTime(), label));
+  timings_.push_back(Timing(kind_, label));
   ATRACE_BEGIN(label);
 }
 
 void TimingLogger::EndTiming() {
-  timings_.push_back(Timing(NanoTime(), nullptr));
+  timings_.push_back(Timing(kind_, nullptr));
   ATRACE_END();
 }
 
diff --git a/runtime/base/timing_logger.h b/runtime/base/timing_logger.h
index a5344dbd31..a8a6701822 100644
--- a/runtime/base/timing_logger.h
+++ b/runtime/base/timing_logger.h
@@ -20,6 +20,7 @@
 #include "base/histogram.h"
 #include "base/macros.h"
 #include "base/mutex.h"
+#include "base/time_utils.h"
 
 #include <set>
 #include <string>
@@ -79,9 +80,23 @@ class TimingLogger {
  public:
   static constexpr size_t kIndexNotFound = static_cast<size_t>(-1);
 
+  // Kind of timing we are going to do. We collect time at the nano second.
+  enum class TimingKind {
+    kMonotonic,
+    kThreadCpu,
+  };
+
   class Timing {
    public:
-    Timing(uint64_t time, const char* name) : time_(time), name_(name) {
+    Timing(TimingKind kind, const char* name) : name_(name) {
+       switch (kind) {
+        case TimingKind::kMonotonic:
+          time_ = NanoTime();
+          break;
+        case TimingKind::kThreadCpu:
+          time_ = ThreadCpuNanoTime();
+          break;
+       }
     }
     bool IsStartTiming() const {
       return !IsEndTiming();
@@ -131,7 +146,10 @@ class TimingLogger {
     friend class TimingLogger;
   };
 
-  TimingLogger(const char* name, bool precise, bool verbose);
+  TimingLogger(const char* name,
+               bool precise,
+               bool verbose,
+               TimingKind kind = TimingKind::kMonotonic);
   ~TimingLogger();
   // Verify that all open timings have related closed timings.
   void Verify();
@@ -187,6 +205,8 @@ class TimingLogger {
   const bool precise_;
   // Verbose logging.
   const bool verbose_;
+  // The kind of timing we want.
+  const TimingKind kind_;
   // 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_;
diff --git a/runtime/base/timing_logger_test.cc b/runtime/base/timing_logger_test.cc
index 35a73d0a76..770d2c0edd 100644
--- a/runtime/base/timing_logger_test.cc
+++ b/runtime/base/timing_logger_test.cc
@@ -158,4 +158,21 @@ TEST_F(TimingLoggerTest, ScopedAndExplicit) {
   EXPECT_LE(timings[idx_innerinnersplit1].GetTime(), timings[idx_innerinnersplit2].GetTime());
 }
 
+TEST_F(TimingLoggerTest, ThreadCpuAndMonotonic) {
+  TimingLogger mon_logger("Scoped", true, false, TimingLogger::TimingKind::kMonotonic);
+  TimingLogger cpu_logger("Scoped", true, false, TimingLogger::TimingKind::kThreadCpu);
+  mon_logger.StartTiming("MON");
+  cpu_logger.StartTiming("CPU");
+
+  sleep(2);
+
+  cpu_logger.EndTiming();
+  mon_logger.EndTiming();
+  uint64_t mon_timing = mon_logger.GetTimings()[1].GetTime() - mon_logger.GetTimings()[0].GetTime();
+  uint64_t cpu_timing = cpu_logger.GetTimings()[1].GetTime() - cpu_logger.GetTimings()[0].GetTime();
+  EXPECT_LT(cpu_timing, MsToNs(1000u));
+  EXPECT_GT(mon_timing, MsToNs(1000u));
+  EXPECT_LT(cpu_timing, mon_timing);
+}
+
 }  // namespace art