Add timing logger to Quick compiler
Current Quick compiler breakdown for compiling the boot class path:
MIR2LIR: 29.674%
MIROpt:SSATransform: 17.656%
MIROpt:BBOpt: 11.508%
BuildMIRGraph: 7.815%
Assemble: 6.898%
MIROpt:ConstantProp: 5.151%
Cleanup: 4.916%
MIROpt:NullCheckElimination: 4.085%
RegisterAllocation: 3.972%
GcMap: 2.359%
Launchpads: 2.147%
PcMappingTable: 2.145%
MIROpt:CodeLayout: 0.697%
LiteralData: 0.654%
SpecialMIR2LIR: 0.323%
Change-Id: I9f77e825faf79e6f6b214bb42edcc4b36f55d291
diff --git a/compiler/dex/compiler_ir.h b/compiler/dex/compiler_ir.h
index bdc3154..0d7209e 100644
--- a/compiler/dex/compiler_ir.h
+++ b/compiler/dex/compiler_ir.h
@@ -29,6 +29,7 @@
#include "llvm/intrinsic_helper.h"
#include "llvm/ir_builder.h"
#include "safe_map.h"
+#include "base/timing_logger.h"
namespace art {
@@ -68,7 +69,14 @@
compiler_flip_match(false),
arena(pool),
mir_graph(NULL),
- cg(NULL) {}
+ cg(NULL),
+ timings("QuickCompiler", true, false) {
+ }
+
+ void StartTimingSplit(const char* label);
+ void NewTimingSplit(const char* label);
+ void EndTiming();
+
/*
* Fields needed/generated by common frontend and generally used throughout
* the compiler.
@@ -109,6 +117,7 @@
UniquePtr<MIRGraph> mir_graph; // MIR container.
UniquePtr<Backend> cg; // Target-specific codegen.
+ base::TimingLogger timings;
};
} // namespace art
diff --git a/compiler/dex/frontend.cc b/compiler/dex/frontend.cc
index 2952570..2f8521f 100644
--- a/compiler/dex/frontend.cc
+++ b/compiler/dex/frontend.cc
@@ -24,6 +24,7 @@
#include "runtime.h"
#include "backend.h"
#include "base/logging.h"
+#include "base/timing_logger.h"
#if defined(ART_USE_PORTABLE_COMPILER)
#include "dex/portable/mir_to_gbc.h"
@@ -104,8 +105,30 @@
// (1 << kDebugVerifyBitcode) |
// (1 << kDebugShowSummaryMemoryUsage) |
// (1 << kDebugShowFilterStats) |
+ // (1 << kDebugTimings) |
0;
+// TODO: Add a cumulative version of logging, and combine with dex2oat --dump-timing
+void CompilationUnit::StartTimingSplit(const char* label) {
+ if (enable_debug & (1 << kDebugTimings)) {
+ timings.StartSplit(label);
+ }
+}
+
+void CompilationUnit::NewTimingSplit(const char* label) {
+ if (enable_debug & (1 << kDebugTimings)) {
+ timings.NewSplit(label);
+ }
+}
+
+void CompilationUnit::EndTiming() {
+ if (enable_debug & (1 << kDebugTimings)) {
+ timings.EndSplit();
+ LOG(INFO) << "TIMINGS " << PrettyMethod(method_idx, *dex_file);
+ LOG(INFO) << Dumpable<base::TimingLogger>(timings);
+ }
+}
+
static CompiledMethod* CompileMethod(CompilerDriver& compiler,
const CompilerBackend compiler_backend,
const DexFile::CodeItem* code_item,
@@ -175,6 +198,7 @@
(1 << kPromoteCompilerTemps));
}
+ cu.StartTimingSplit("BuildMIRGraph");
cu.mir_graph.reset(new MIRGraph(&cu, &cu.arena));
/* Gathering opcode stats? */
@@ -192,22 +216,28 @@
}
#endif
+ cu.NewTimingSplit("MIROpt:CodeLayout");
+
/* Do a code layout pass */
cu.mir_graph->CodeLayout();
/* Perform SSA transformation for the whole method */
+ cu.NewTimingSplit("MIROpt:SSATransform");
cu.mir_graph->SSATransformation();
/* Do constant propagation */
+ cu.NewTimingSplit("MIROpt:ConstantProp");
cu.mir_graph->PropagateConstants();
/* Count uses */
cu.mir_graph->MethodUseCount();
/* Perform null check elimination */
+ cu.NewTimingSplit("MIROpt:NullCheckElimination");
cu.mir_graph->NullCheckElimination();
/* Combine basic blocks where possible */
+ cu.NewTimingSplit("MIROpt:BBOpt");
cu.mir_graph->BasicBlockCombine();
/* Do some basic block optimizations */
@@ -250,6 +280,7 @@
cu.cg->Materialize();
+ cu.NewTimingSplit("Cleanup");
result = cu.cg->GetCompiledMethod();
if (result) {
@@ -270,6 +301,7 @@
<< " " << PrettyMethod(method_idx, dex_file);
}
+ cu.EndTiming();
return result;
}
diff --git a/compiler/dex/frontend.h b/compiler/dex/frontend.h
index 6c33d10..43f6855 100644
--- a/compiler/dex/frontend.h
+++ b/compiler/dex/frontend.h
@@ -78,6 +78,7 @@
kDebugVerifyBitcode,
kDebugShowSummaryMemoryUsage,
kDebugShowFilterStats,
+ kDebugTimings
};
class LLVMInfo {
diff --git a/compiler/dex/quick/arm/assemble_arm.cc b/compiler/dex/quick/arm/assemble_arm.cc
index cc40e99..2a6e656 100644
--- a/compiler/dex/quick/arm/assemble_arm.cc
+++ b/compiler/dex/quick/arm/assemble_arm.cc
@@ -1153,6 +1153,7 @@
void ArmMir2Lir::AssembleLIR() {
LIR* lir;
LIR* prev_lir;
+ cu_->NewTimingSplit("Assemble");
int assembler_retries = 0;
CodeOffset starting_offset = EncodeRange(first_lir_insn_, last_lir_insn_, 0);
data_offset_ = (starting_offset + 0x3) & ~0x3;
@@ -1574,6 +1575,7 @@
data_offset_ = (code_buffer_.size() + 0x3) & ~0x3;
+ cu_->NewTimingSplit("LiteralData");
// Install literals
InstallLiteralPools();
@@ -1584,8 +1586,10 @@
InstallFillArrayData();
// Create the mapping table and native offset to reference map.
+ cu_->NewTimingSplit("PcMappingTable");
CreateMappingTables();
+ cu_->NewTimingSplit("GcMap");
CreateNativeGcMap();
}
diff --git a/compiler/dex/quick/codegen_util.cc b/compiler/dex/quick/codegen_util.cc
index 2ce8f58..a6653fa 100644
--- a/compiler/dex/quick/codegen_util.cc
+++ b/compiler/dex/quick/codegen_util.cc
@@ -929,6 +929,7 @@
}
void Mir2Lir::Materialize() {
+ cu_->NewTimingSplit("RegisterAllocation");
CompilerInitializeRegAlloc(); // Needs to happen after SSA naming
/* Allocate Registers using simple local allocation scheme */
@@ -940,6 +941,7 @@
* special codegen doesn't succeed, first_lir_insn_ will
* set to NULL;
*/
+ cu_->NewTimingSplit("SpecialMIR2LIR");
SpecialMIR2LIR(mir_graph_->GetSpecialCase());
}
diff --git a/compiler/dex/quick/mips/assemble_mips.cc b/compiler/dex/quick/mips/assemble_mips.cc
index ea8b7a6..5f5e5e4 100644
--- a/compiler/dex/quick/mips/assemble_mips.cc
+++ b/compiler/dex/quick/mips/assemble_mips.cc
@@ -768,6 +768,7 @@
* TODO: consolidate w/ Arm assembly mechanism.
*/
void MipsMir2Lir::AssembleLIR() {
+ cu_->NewTimingSplit("Assemble");
AssignOffsets();
int assembler_retries = 0;
/*
@@ -792,6 +793,7 @@
}
// Install literals
+ cu_->NewTimingSplit("LiteralData");
InstallLiteralPools();
// Install switch tables
@@ -801,8 +803,10 @@
InstallFillArrayData();
// Create the mapping table and native offset to reference map.
+ cu_->NewTimingSplit("PcMappingTable");
CreateMappingTables();
+ cu_->NewTimingSplit("GcMap");
CreateNativeGcMap();
}
diff --git a/compiler/dex/quick/mir_to_lir.cc b/compiler/dex/quick/mir_to_lir.cc
index 197e200..fa9a3ad 100644
--- a/compiler/dex/quick/mir_to_lir.cc
+++ b/compiler/dex/quick/mir_to_lir.cc
@@ -819,6 +819,8 @@
}
void Mir2Lir::MethodMIR2LIR() {
+ cu_->NewTimingSplit("MIR2LIR");
+
// Hold the labels of each block.
block_label_list_ =
static_cast<LIR*>(arena_->Alloc(sizeof(LIR) * mir_graph_->GetNumBlocks(),
@@ -839,7 +841,7 @@
next_bb = iter.Next();
} while ((next_bb != NULL) && (next_bb->block_type == kDead));
}
-
+ cu_->NewTimingSplit("Launchpads");
HandleSuspendLaunchPads();
HandleThrowLaunchPads();
diff --git a/compiler/dex/quick/x86/assemble_x86.cc b/compiler/dex/quick/x86/assemble_x86.cc
index fb8e75f..0e30260 100644
--- a/compiler/dex/quick/x86/assemble_x86.cc
+++ b/compiler/dex/quick/x86/assemble_x86.cc
@@ -1443,6 +1443,7 @@
* TODO: consolidate w/ Arm assembly mechanism.
*/
void X86Mir2Lir::AssembleLIR() {
+ cu_->NewTimingSplit("Assemble");
AssignOffsets();
int assembler_retries = 0;
/*
@@ -1466,6 +1467,7 @@
}
}
+ cu_->NewTimingSplit("LiteralData");
// Install literals
InstallLiteralPools();
@@ -1476,8 +1478,10 @@
InstallFillArrayData();
// Create the mapping table and native offset to reference map.
+ cu_->NewTimingSplit("PcMappingTable");
CreateMappingTables();
+ cu_->NewTimingSplit("GcMap");
CreateNativeGcMap();
}
