Merge "If dex2oat takes >1s, show a breakdown of where the time went." into dalvik-dev
diff --git a/src/compiler.cc b/src/compiler.cc
index a3bb985..02367d3 100644
--- a/src/compiler.cc
+++ b/src/compiler.cc
@@ -29,6 +29,7 @@
 #include "object_utils.h"
 #include "runtime.h"
 #include "stl_util.h"
+#include "timing_logger.h"
 
 namespace art {
 
@@ -138,9 +139,19 @@
                           const std::vector<const DexFile*>& dex_files) {
   DCHECK(!Runtime::Current()->IsStarted());
 
-  PreCompile(class_loader, dex_files);
+  TimingLogger timings("compiler");
+
+  PreCompile(class_loader, dex_files, timings);
+
   Compile(class_loader, dex_files);
+  timings.AddSplit("Compile");
+
   PostCompile(class_loader, dex_files);
+  timings.AddSplit("PostCompile");
+
+  if (timings.GetTotalNs() > MsToNs(1000)) {
+    timings.Dump();
+  }
 }
 
 void Compiler::CompileOne(const Method* method) {
@@ -154,7 +165,8 @@
   std::vector<const DexFile*> dex_files;
   dex_files.push_back(&dex_file);
 
-  PreCompile(class_loader, dex_files);
+  TimingLogger timings("CompileOne");
+  PreCompile(class_loader, dex_files, timings);
 
   uint32_t method_idx = method->GetDexMethodIndex();
   const DexFile::CodeItem* code_item = dex_file.GetCodeItem(method->GetCodeItemOffset());
@@ -173,10 +185,15 @@
 }
 
 void Compiler::PreCompile(const ClassLoader* class_loader,
-                          const std::vector<const DexFile*>& dex_files) {
+                          const std::vector<const DexFile*>& dex_files, TimingLogger& timings) {
   Resolve(class_loader, dex_files);
+  timings.AddSplit("PreCompile.Resolve");
+
   Verify(class_loader, dex_files);
+  timings.AddSplit("PreCompile.Verify");
+
   InitializeClassesWithoutClinit(class_loader, dex_files);
+  timings.AddSplit("PreCompile.InitializeClassesWithoutClinit");
 }
 
 void Compiler::PostCompile(const ClassLoader* class_loader,
diff --git a/src/compiler.h b/src/compiler.h
index 6c67298..7b66d52 100644
--- a/src/compiler.h
+++ b/src/compiler.h
@@ -33,6 +33,8 @@
 
 namespace art {
 
+class TimingLogger;
+
 class Compiler {
  public:
   // Create a compiler targeting the requested "instruction_set".
@@ -109,7 +111,7 @@
   // Checks if class specified by type_idx is one of the image_classes_
   bool IsImageClass(const std::string& descriptor) const;
 
-  void PreCompile(const ClassLoader* class_loader, const std::vector<const DexFile*>& dex_files);
+  void PreCompile(const ClassLoader* class_loader, const std::vector<const DexFile*>& dex_files, TimingLogger& timing);
   void PostCompile(const ClassLoader* class_loader, const std::vector<const DexFile*>& dex_files);
 
   // Attempt to resolve all type, methods, fields, and strings
diff --git a/src/timing_logger.h b/src/timing_logger.h
index b8e545e..594ae98 100644
--- a/src/timing_logger.h
+++ b/src/timing_logger.h
@@ -41,9 +41,13 @@
   void Dump() {
     LOG(INFO) << name_ << ": begin";
     for (size_t i = 1; i < times_.size(); ++i) {
-      LOG(INFO) << name_ << ": " << PrettyDuration(times_[i] - times_[i-1]) << labels_[i];
+      LOG(INFO) << name_ << StringPrintf(": %8lld ms, ", NsToMs(times_[i] - times_[i-1])) << labels_[i];
     }
-    LOG(INFO) << name_ << ": end, " << PrettyDuration(times_.back() - times_.front());
+    LOG(INFO) << name_ << ": end, " << NsToMs(GetTotalNs()) << " ms";
+  }
+
+  uint64_t GetTotalNs() {
+    return times_.back() - times_.front();
   }
 
  private:
diff --git a/src/utils.h b/src/utils.h
index 7daa4f9..d88fa2b 100644
--- a/src/utils.h
+++ b/src/utils.h
@@ -256,7 +256,6 @@
   return ns * 1000 * 1000;
 }
 
-
 // Splits a string using the given delimiter character into a vector of
 // strings. Empty strings will be omitted.
 void Split(const std::string& s, char delim, std::vector<std::string>& result);