commit a61f49539a59b610e557b5513695295639496750
author buzbee <buzbee@google.com> Fri Aug 23 14:27:06 2013 -0700
committer buzbee <buzbee@google.com> Fri Oct 25 07:42:26 2013 -0700
tree f2a52e9e5b3db371cf0407614b51bc27397c39d3
parent 1984152ac92aad244ae15184d12f9ceade686b7b

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

compiler/dex/frontend.cc

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