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;
}