Change JIT timings to collect thread CPU time.
Test: m
Test: timing_logger_test.cc
Change-Id: I26fd86e66c4dd967dc62b629f6b6cde97b71ed13
diff --git a/compiler/jit/jit_compiler.cc b/compiler/jit/jit_compiler.cc
index 5fdf9ff..511a44a 100644
--- a/compiler/jit/jit_compiler.cc
+++ b/compiler/jit/jit_compiler.cc
@@ -175,7 +175,8 @@
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 b2e5251..b8d6931 100644
--- a/runtime/base/timing_logger.cc
+++ b/runtime/base/timing_logger.cc
@@ -128,8 +128,11 @@
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::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 a5344db..a8a6701 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 @@
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 @@
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 @@
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 35a73d0..770d2c0 100644
--- a/runtime/base/timing_logger_test.cc
+++ b/runtime/base/timing_logger_test.cc
@@ -158,4 +158,21 @@
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