Re-apply: Implement cumulative timings for CompilerDriver.
The bug was due to how the test infrastructure works:
a compiler driver surives the stack where it is allocated.
Change-Id: I345fe0e4afb2bd15937233db8afb350f09429558
diff --git a/compiler/dex/frontend.cc b/compiler/dex/frontend.cc
index c2016d0..8f83cd0 100644
--- a/compiler/dex/frontend.cc
+++ b/compiler/dex/frontend.cc
@@ -140,24 +140,25 @@
CompilationUnit::~CompilationUnit() {
}
-// TODO: Add a cumulative version of logging, and combine with dex2oat --dump-timing
void CompilationUnit::StartTimingSplit(const char* label) {
- if (enable_debug & (1 << kDebugTimings)) {
+ if (compiler_driver->GetDumpPasses()) {
timings.StartSplit(label);
}
}
void CompilationUnit::NewTimingSplit(const char* label) {
- if (enable_debug & (1 << kDebugTimings)) {
+ if (compiler_driver->GetDumpPasses()) {
timings.NewSplit(label);
}
}
void CompilationUnit::EndTiming() {
- if (enable_debug & (1 << kDebugTimings)) {
+ if (compiler_driver->GetDumpPasses()) {
timings.EndSplit();
- LOG(INFO) << "TIMINGS " << PrettyMethod(method_idx, *dex_file);
- LOG(INFO) << Dumpable<TimingLogger>(timings);
+ if (enable_debug & (1 << kDebugTimings)) {
+ LOG(INFO) << "TIMINGS " << PrettyMethod(method_idx, *dex_file);
+ LOG(INFO) << Dumpable<TimingLogger>(timings);
+ }
}
}
@@ -330,6 +331,9 @@
}
cu.EndTiming();
+ compiler.GetTimingsLogger().Start();
+ compiler.GetTimingsLogger().AddLogger(cu.timings);
+ compiler.GetTimingsLogger().End();
return result;
}
diff --git a/compiler/driver/compiler_driver.cc b/compiler/driver/compiler_driver.cc
index 9f48351..c8fe4a8 100644
--- a/compiler/driver/compiler_driver.cc
+++ b/compiler/driver/compiler_driver.cc
@@ -342,7 +342,7 @@
CompilerBackend compiler_backend, InstructionSet instruction_set,
InstructionSetFeatures instruction_set_features,
bool image, DescriptorSet* image_classes, size_t thread_count,
- bool dump_stats)
+ bool dump_stats, bool dump_passes, CumulativeLogger* timer)
: verification_results_(verification_results),
method_inliner_map_(method_inliner_map),
compiler_backend_(compiler_backend),
@@ -357,6 +357,8 @@
start_ns_(0),
stats_(new AOTCompilationStats),
dump_stats_(dump_stats),
+ dump_passes_(dump_passes),
+ timings_logger_(timer),
compiler_library_(NULL),
compiler_(NULL),
compiler_context_(NULL),
diff --git a/compiler/driver/compiler_driver.h b/compiler/driver/compiler_driver.h
index 4307212..c562f76 100644
--- a/compiler/driver/compiler_driver.h
+++ b/compiler/driver/compiler_driver.h
@@ -22,6 +22,7 @@
#include <vector>
#include "base/mutex.h"
+#include "base/timing_logger.h"
#include "class_reference.h"
#include "compiled_class.h"
#include "compiled_method.h"
@@ -98,7 +99,8 @@
CompilerBackend compiler_backend, InstructionSet instruction_set,
InstructionSetFeatures instruction_set_features,
bool image, DescriptorSet* image_classes,
- size_t thread_count, bool dump_stats);
+ size_t thread_count, bool dump_stats, bool dump_passes,
+ CumulativeLogger* timer);
~CompilerDriver();
@@ -281,6 +283,15 @@
class CallPatchInformation;
class TypePatchInformation;
+
+ bool GetDumpPasses() const {
+ return dump_passes_;
+ }
+
+ CumulativeLogger& GetTimingsLogger() const {
+ return *timings_logger_;
+ }
+
class PatchInformation {
public:
const DexFile& GetDexFile() const {
@@ -523,6 +534,9 @@
UniquePtr<AOTCompilationStats> stats_;
bool dump_stats_;
+ const bool dump_passes_;
+
+ CumulativeLogger* const timings_logger_;
typedef void (*CompilerCallbackFn)(CompilerDriver& driver);
typedef MutexLock* (*CompilerMutexLockFn)(CompilerDriver& driver);
diff --git a/compiler/oat_test.cc b/compiler/oat_test.cc
index b3070b6..f6b511c 100644
--- a/compiler/oat_test.cc
+++ b/compiler/oat_test.cc
@@ -91,10 +91,12 @@
verification_results_.reset(new VerificationResults);
method_inliner_map_.reset(compiler_backend == kQuick ? new DexFileToMethodInlinerMap : nullptr);
callbacks_.Reset(verification_results_.get(), method_inliner_map_.get());
+ timer_.reset(new CumulativeLogger("Compilation times"));
compiler_driver_.reset(new CompilerDriver(verification_results_.get(),
method_inliner_map_.get(),
compiler_backend, insn_set,
- insn_features, false, NULL, 2, true));
+ insn_features, false, NULL, 2, true, true,
+ timer_.get()));
jobject class_loader = NULL;
if (kCompile) {
TimingLogger timings("OatTest::WriteRead", false, false);
diff --git a/dex2oat/dex2oat.cc b/dex2oat/dex2oat.cc
index 5ac01f2..6c2c8b0 100644
--- a/dex2oat/dex2oat.cc
+++ b/dex2oat/dex2oat.cc
@@ -253,7 +253,9 @@
bool image,
UniquePtr<CompilerDriver::DescriptorSet>& image_classes,
bool dump_stats,
- TimingLogger& timings) {
+ bool dump_passes,
+ TimingLogger& timings,
+ CumulativeLogger& compiler_phases_timings) {
// SirtRef and ClassLoader creation needs to come after Runtime::Create
jobject class_loader = NULL;
Thread* self = Thread::Current();
@@ -280,7 +282,9 @@
image,
image_classes.release(),
thread_count_,
- dump_stats));
+ dump_stats,
+ dump_passes,
+ &compiler_phases_timings));
if (compiler_backend_ == kPortable) {
driver->SetBitcodeFileName(bitcode_filename);
@@ -654,6 +658,7 @@
static int dex2oat(int argc, char** argv) {
TimingLogger timings("compiler", false, false);
+ CumulativeLogger compiler_phases_timings("compilation times");
InitLogging(argv);
@@ -703,6 +708,7 @@
bool is_host = false;
bool dump_stats = false;
bool dump_timing = false;
+ bool dump_passes = false;
bool dump_slow_timing = kIsDebugBuild;
bool watch_dog_enabled = !kIsTargetBuild;
@@ -798,6 +804,8 @@
runtime_args.push_back(argv[i]);
} else if (option == "--dump-timing") {
dump_timing = true;
+ } else if (option == "--dump-passes") {
+ dump_passes = true;
} else if (option == "--dump-stats") {
dump_stats = true;
} else {
@@ -1069,7 +1077,9 @@
image,
image_classes,
dump_stats,
- timings));
+ dump_passes,
+ timings,
+ compiler_phases_timings));
if (compiler.get() == NULL) {
LOG(ERROR) << "Failed to create oat file: " << oat_location;
@@ -1145,6 +1155,9 @@
if (dump_timing || (dump_slow_timing && timings.GetTotalNs() > MsToNs(1000))) {
LOG(INFO) << Dumpable<TimingLogger>(timings);
}
+ if (dump_passes) {
+ LOG(INFO) << Dumpable<CumulativeLogger>(compiler.get()->GetTimingsLogger());
+ }
return EXIT_SUCCESS;
}
@@ -1187,6 +1200,9 @@
if (dump_timing || (dump_slow_timing && timings.GetTotalNs() > MsToNs(1000))) {
LOG(INFO) << Dumpable<TimingLogger>(timings);
}
+ if (dump_passes) {
+ LOG(INFO) << Dumpable<CumulativeLogger>(compiler_phases_timings);
+ }
// Everything was successfully written, do an explicit exit here to avoid running Runtime
// destructors that take time (bug 10645725) unless we're a debug build or running on valgrind.
diff --git a/runtime/common_test.h b/runtime/common_test.h
index ddaf52a..f37fb5c 100644
--- a/runtime/common_test.h
+++ b/runtime/common_test.h
@@ -480,12 +480,13 @@
}
}
class_linker_->FixupDexCaches(runtime_->GetResolutionMethod());
+ timer_.reset(new CumulativeLogger("Compilation times"));
compiler_driver_.reset(new CompilerDriver(verification_results_.get(),
method_inliner_map_.get(),
compiler_backend, instruction_set,
instruction_set_features,
true, new CompilerDriver::DescriptorSet,
- 2, true));
+ 2, true, true, timer_.get()));
}
// We typically don't generate an image in unit tests, disable this optimization by default.
compiler_driver_->SetSupportBootImageFixup(false);
@@ -530,6 +531,7 @@
(*icu_cleanup_fn)();
compiler_driver_.reset();
+ timer_.reset();
callbacks_.Reset(nullptr, nullptr);
method_inliner_map_.reset();
verification_results_.reset();
@@ -662,7 +664,7 @@
class TestCompilerCallbacks : public CompilerCallbacks {
public:
- TestCompilerCallbacks() : verification_results_(nullptr), method_inliner_map_(nullptr) { }
+ TestCompilerCallbacks() : verification_results_(nullptr), method_inliner_map_(nullptr) {}
void Reset(VerificationResults* verification_results,
DexFileToMethodInlinerMap* method_inliner_map) {
@@ -701,6 +703,7 @@
UniquePtr<DexFileToMethodInlinerMap> method_inliner_map_;
TestCompilerCallbacks callbacks_;
UniquePtr<CompilerDriver> compiler_driver_;
+ UniquePtr<CumulativeLogger> timer_;
private:
std::vector<const DexFile*> opened_dex_files_;