Add way to print JIT related info at shutdown
Added a runtime option called -XX:DumpJITInfoOnShutdown with prints
various interesting JIT statistics during the shutdown of the runtime
if enabled.
Example of running EvaluateAndApplyChanges with the option:
I art : Code cache size=427KB data cache size=84KB num methods=1598
I art : Start Dumping histograms for 1598 iterations for JIT timings
I art : Compiling: Sum: 727.850ms 99% C.I. 135us-4402us Avg: 455.475us Max: 15567us
I art : Verifying: Sum: 191.074ms 99% C.I. 19us-1450.500us Avg: 119.570us Max: 5142us
I art : TrimMaps: Sum: 62.053ms 99% C.I. 13us-199.374us Avg: 38.831us Max: 10058us
I art : MakeExecutable: Sum: 11.153ms 99% C.I. 4us-47us Avg: 6.979us Max: 47us
I art : Initializing: Sum: 7.991ms 99% C.I. 1us-49.781us Avg: 5us Max: 4852us
I art : Done Dumping histograms
Bug: 17950037
Change-Id: I23538b24f947e5f6934f55579b8baa9d806eb3d5
diff --git a/compiler/jit/jit_compiler.cc b/compiler/jit/jit_compiler.cc
index a63e14a..beb5755 100644
--- a/compiler/jit/jit_compiler.cc
+++ b/compiler/jit/jit_compiler.cc
@@ -18,6 +18,7 @@
#include "arch/instruction_set.h"
#include "arch/instruction_set_features.h"
+#include "base/timing_logger.h"
#include "compiler_callbacks.h"
#include "dex/pass_manager.h"
#include "dex/quick_compiler_callbacks.h"
@@ -103,6 +104,7 @@
}
bool JitCompiler::CompileMethod(Thread* self, mirror::ArtMethod* method) {
+ TimingLogger logger("JIT compiler timing logger", true, VLOG_IS_ON(jit));
const uint64_t start_time = NanoTime();
StackHandleScope<2> hs(self);
self->AssertNoPendingException();
@@ -113,14 +115,18 @@
return true; // Already compiled
}
Handle<mirror::Class> h_class(hs.NewHandle(h_method->GetDeclaringClass()));
- if (!runtime->GetClassLinker()->EnsureInitialized(self, h_class, true, true)) {
- VLOG(jit) << "JIT failed to initialize " << PrettyMethod(h_method.Get());
- return false;
+ {
+ TimingLogger::ScopedTiming t2("Initializing", &logger);
+ if (!runtime->GetClassLinker()->EnsureInitialized(self, h_class, true, true)) {
+ VLOG(jit) << "JIT failed to initialize " << PrettyMethod(h_method.Get());
+ return false;
+ }
}
const DexFile* dex_file = h_class->GetDexCache()->GetDexFile();
MethodReference method_ref(dex_file, h_method->GetDexMethodIndex());
// Only verify if we don't already have verification results.
if (verification_results_->GetVerifiedMethod(method_ref) == nullptr) {
+ TimingLogger::ScopedTiming t2("Verifying", &logger);
std::string error;
if (verifier::MethodVerifier::VerifyMethod(h_method.Get(), true, &error) ==
verifier::MethodVerifier::kHardFailure) {
@@ -129,9 +135,16 @@
return false;
}
}
- CompiledMethod* compiled_method(compiler_driver_->CompileMethod(self, h_method.Get()));
- // Trim maps to reduce memory usage, TODO: measure how much this increases compile time.
- runtime->GetArenaPool()->TrimMaps();
+ CompiledMethod* compiled_method = nullptr;
+ {
+ TimingLogger::ScopedTiming t2("Compiling", &logger);
+ compiled_method = compiler_driver_->CompileMethod(self, h_method.Get());
+ }
+ {
+ TimingLogger::ScopedTiming t2("TrimMaps", &logger);
+ // Trim maps to reduce memory usage, TODO: measure how much this increases compile time.
+ runtime->GetArenaPool()->TrimMaps();
+ }
if (compiled_method == nullptr) {
return false;
}
@@ -147,11 +160,13 @@
h_method->SetEntryPointFromQuickCompiledCode(code);
result = true;
} else {
+ TimingLogger::ScopedTiming t2("MakeExecutable", &logger);
result = MakeExecutable(compiled_method, h_method.Get());
}
}
// Remove the compiled method to save memory.
compiler_driver_->RemoveCompiledMethod(method_ref);
+ runtime->GetJit()->AddTimingLogger(logger);
return result;
}
diff --git a/runtime/jit/jit.cc b/runtime/jit/jit.cc
index 539c181..9b89459 100644
--- a/runtime/jit/jit.cc
+++ b/runtime/jit/jit.cc
@@ -40,16 +40,32 @@
options.GetOrDefault(RuntimeArgumentMap::JITCodeCacheCapacity);
jit_options->compile_threshold_ =
options.GetOrDefault(RuntimeArgumentMap::JITCompileThreshold);
+ jit_options->dump_info_on_shutdown_ =
+ options.Exists(RuntimeArgumentMap::DumpJITInfoOnShutdown);
return jit_options;
}
+void Jit::DumpInfo(std::ostream& os) {
+ os << "Code cache size=" << PrettySize(code_cache_->CodeCacheSize())
+ << " data cache size=" << PrettySize(code_cache_->DataCacheSize())
+ << " num methods=" << code_cache_->NumMethods()
+ << "\n";
+ cumulative_timings_.Dump(os);
+}
+
+void Jit::AddTimingLogger(const TimingLogger& logger) {
+ cumulative_timings_.AddLogger(logger);
+}
+
Jit::Jit()
: jit_library_handle_(nullptr), jit_compiler_handle_(nullptr), jit_load_(nullptr),
- jit_compile_method_(nullptr) {
+ jit_compile_method_(nullptr), dump_info_on_shutdown_(false),
+ cumulative_timings_("JIT timings") {
}
Jit* Jit::Create(JitOptions* options, std::string* error_msg) {
std::unique_ptr<Jit> jit(new Jit);
+ jit->dump_info_on_shutdown_ = options->DumpJitInfoOnShutdown();
if (!jit->LoadCompiler(error_msg)) {
return nullptr;
}
@@ -133,6 +149,9 @@
}
Jit::~Jit() {
+ if (dump_info_on_shutdown_) {
+ DumpInfo(LOG(INFO));
+ }
DeleteThreadPool();
if (jit_compiler_handle_ != nullptr) {
jit_unload_(jit_compiler_handle_);
diff --git a/runtime/jit/jit.h b/runtime/jit/jit.h
index b80015f..6b206d1 100644
--- a/runtime/jit/jit.h
+++ b/runtime/jit/jit.h
@@ -24,6 +24,7 @@
#include "atomic.h"
#include "base/macros.h"
#include "base/mutex.h"
+#include "base/timing_logger.h"
#include "gc_root.h"
#include "jni.h"
#include "object_callbacks.h"
@@ -61,6 +62,11 @@
return code_cache_.get();
}
void DeleteThreadPool();
+ // Dump interesting info: #methods compiled, code vs data size, compile / verify cumulative
+ // loggers.
+ void DumpInfo(std::ostream& os);
+ // Add a timing logger to cumulative_timings_.
+ void AddTimingLogger(const TimingLogger& logger);
private:
Jit();
@@ -73,6 +79,10 @@
void (*jit_unload_)(void*);
bool (*jit_compile_method_)(void*, mirror::ArtMethod*, Thread*);
+ // Performance monitoring.
+ bool dump_info_on_shutdown_;
+ CumulativeLogger cumulative_timings_;
+
std::unique_ptr<jit::JitInstrumentationCache> instrumentation_cache_;
std::unique_ptr<jit::JitCodeCache> code_cache_;
CompilerCallbacks* compiler_callbacks_; // Owned by the jit compiler.
@@ -87,12 +97,16 @@
size_t GetCodeCacheCapacity() const {
return code_cache_capacity_;
}
+ bool DumpJitInfoOnShutdown() const {
+ return dump_info_on_shutdown_;
+ }
private:
size_t code_cache_capacity_;
size_t compile_threshold_;
+ bool dump_info_on_shutdown_;
- JitOptions() : code_cache_capacity_(0), compile_threshold_(0) {
+ JitOptions() : code_cache_capacity_(0), compile_threshold_(0), dump_info_on_shutdown_(false) {
}
};
diff --git a/runtime/jit/jit_code_cache.cc b/runtime/jit/jit_code_cache.cc
index 4ae4d57..4d367e0 100644
--- a/runtime/jit/jit_code_cache.cc
+++ b/runtime/jit/jit_code_cache.cc
@@ -77,6 +77,7 @@
if (size > CodeCacheRemain()) {
return nullptr;
}
+ ++num_methods_; // TODO: This is hacky but works since each method has exactly one code region.
code_cache_ptr_ += size;
return code_cache_ptr_ - size;
}
diff --git a/runtime/parsed_options.cc b/runtime/parsed_options.cc
index 607569a..a53aeaa 100644
--- a/runtime/parsed_options.cc
+++ b/runtime/parsed_options.cc
@@ -136,6 +136,8 @@
.IntoKey(M::LongGCLogThreshold)
.Define("-XX:DumpGCPerformanceOnShutdown")
.IntoKey(M::DumpGCPerformanceOnShutdown)
+ .Define("-XX:DumpJITInfoOnShutdown")
+ .IntoKey(M::DumpJITInfoOnShutdown)
.Define("-XX:IgnoreMaxFootprint")
.IntoKey(M::IgnoreMaxFootprint)
.Define("-XX:LowMemoryMode")
@@ -620,6 +622,7 @@
UsageMessage(stream, " -XX:LongPauseLogThreshold=integervalue\n");
UsageMessage(stream, " -XX:LongGCLogThreshold=integervalue\n");
UsageMessage(stream, " -XX:DumpGCPerformanceOnShutdown\n");
+ UsageMessage(stream, " -XX:DumpJITInfoOnShutdown\n");
UsageMessage(stream, " -XX:IgnoreMaxFootprint\n");
UsageMessage(stream, " -XX:UseTLAB\n");
UsageMessage(stream, " -XX:BackgroundGC=none\n");
diff --git a/runtime/runtime_options.def b/runtime/runtime_options.def
index d072ffa..8775f8d 100644
--- a/runtime/runtime_options.def
+++ b/runtime/runtime_options.def
@@ -59,6 +59,7 @@
RUNTIME_OPTIONS_KEY (MillisecondsToNanoseconds, \
LongGCLogThreshold, gc::Heap::kDefaultLongGCLogThreshold)
RUNTIME_OPTIONS_KEY (Unit, DumpGCPerformanceOnShutdown)
+RUNTIME_OPTIONS_KEY (Unit, DumpJITInfoOnShutdown)
RUNTIME_OPTIONS_KEY (Unit, IgnoreMaxFootprint)
RUNTIME_OPTIONS_KEY (Unit, LowMemoryMode)
RUNTIME_OPTIONS_KEY (bool, UseTLAB, false)