dex2oat: Change reported data for `--dump-timings`.

In `CompilerDriver`, add summary entry across all dex files
(Resolve, Resolve const-string Strings, Verify, Initialize,
Compile). Remove the dex file-specific "Resolve const-string
Strings" because this entire phase tends to be quite short.

In `OatWriter`, add top-level timings for writing functions.
Remove timings for small parts of `WriteRodata()`.

In `Dex2oat`, add timings for significant parts of oat file
writing.

Test: m test-art-host-gtest
Test: testrunner.py --host --optimizing
Change-Id: Ie4b541b126244a87ec169b76897d74d5d0cab963

3 files changed, 40 insertions, 25 deletions

diff --git a/dex2oat/dex2oat.cc b/dex2oat/dex2oat.cc
index 344c9406f2..e3cc0ec682 100644
--- a/dex2oat/dex2oat.cc
+++ b/dex2oat/dex2oat.cc
@@ -2198,11 +2198,17 @@ class Dex2Oat final {
         }
 
         elf_writer->WriteDynamicSection();
-        elf_writer->WriteDebugInfo(oat_writer->GetDebugInfo());
+        {
+          TimingLogger::ScopedTiming t_wdi("Write DebugInfo", timings_);
+          elf_writer->WriteDebugInfo(oat_writer->GetDebugInfo());
+        }
 
-        if (!elf_writer->End()) {
-          LOG(ERROR) << "Failed to write ELF file " << oat_file->GetPath();
-          return false;
+        {
+          TimingLogger::ScopedTiming t_end("Write ELF End", timings_);
+          if (!elf_writer->End()) {
+            LOG(ERROR) << "Failed to write ELF file " << oat_file->GetPath();
+            return false;
+          }
         }
 
         if (!FlushOutputFile(&vdex_files_[i]) || !FlushOutputFile(&oat_files_[i])) {
@@ -2211,7 +2217,10 @@ class Dex2Oat final {
 
         VLOG(compiler) << "Oat file written successfully: " << oat_filenames_[i];
 
-        oat_writer.reset();
+        {
+          TimingLogger::ScopedTiming t_dow("Destroy OatWriter", timings_);
+          oat_writer.reset();
+        }
         // We may still need the ELF writer later for stripping.
       }
     }
diff --git a/dex2oat/driver/compiler_driver.cc b/dex2oat/driver/compiler_driver.cc
index ddf9bbda84..7f4ec13f1b 100644
--- a/dex2oat/driver/compiler_driver.cc
+++ b/dex2oat/driver/compiler_driver.cc
@@ -565,6 +565,7 @@ static void CompileMethodQuick(
 void CompilerDriver::Resolve(jobject class_loader,
                              const std::vector<const DexFile*>& dex_files,
                              TimingLogger* timings) {
+  TimingLogger::ScopedTiming t("Resolve Types", timings);
   // Resolution allocates classes and needs to run single-threaded to be deterministic.
   bool force_determinism = GetCompilerOptions().IsForceDeterminism();
   ThreadPool* resolve_thread_pool = force_determinism
@@ -586,6 +587,7 @@ void CompilerDriver::Resolve(jobject class_loader,
 void CompilerDriver::ResolveConstStrings(const std::vector<const DexFile*>& dex_files,
                                          bool only_startup_strings,
                                          TimingLogger* timings) {
+  TimingLogger::ScopedTiming t("Resolve const-string Strings", timings);
   const ProfileCompilationInfo* profile_compilation_info =
       GetCompilerOptions().GetProfileCompilationInfo();
   if (only_startup_strings && profile_compilation_info == nullptr) {
@@ -601,7 +603,6 @@ void CompilerDriver::ResolveConstStrings(const std::vector<const DexFile*>& dex_
 
   for (const DexFile* dex_file : dex_files) {
     dex_cache.Assign(class_linker->FindDexCache(soa.Self(), *dex_file));
-    TimingLogger::ScopedTiming t("Resolve const-string Strings", timings);
 
     ProfileCompilationInfo::ProfileIndexType profile_index =
         ProfileCompilationInfo::MaxProfileIndex();
@@ -1767,7 +1768,7 @@ void CompilerDriver::ResolveDexFile(jobject class_loader,
                                     size_t thread_count,
                                     TimingLogger* timings) {
   ScopedTrace trace(__FUNCTION__);
-  TimingLogger::ScopedTiming t("Resolve Types", timings);
+  TimingLogger::ScopedTiming t("Resolve Dex File", timings);
   ClassLinker* class_linker = Runtime::Current()->GetClassLinker();
 
   // TODO: we could resolve strings here, although the string table is largely filled with class
@@ -1932,18 +1933,21 @@ void CompilerDriver::Verify(jobject jclass_loader,
     }
   }
 
-  // Verification updates VerifierDeps and needs to run single-threaded to be deterministic.
-  bool force_determinism = GetCompilerOptions().IsForceDeterminism();
-  ThreadPool* verify_thread_pool =
-      force_determinism ? single_thread_pool_.get() : parallel_thread_pool_.get();
-  size_t verify_thread_count = force_determinism ? 1U : parallel_thread_count_;
-  for (const DexFile* dex_file : dex_files) {
-    CHECK(dex_file != nullptr);
-    VerifyDexFile(jclass_loader,
-                  *dex_file,
-                  verify_thread_pool,
-                  verify_thread_count,
-                  timings);
+  {
+    TimingLogger::ScopedTiming t("Verify Classes", timings);
+    // Verification updates VerifierDeps and needs to run single-threaded to be deterministic.
+    bool force_determinism = GetCompilerOptions().IsForceDeterminism();
+    ThreadPool* verify_thread_pool =
+        force_determinism ? single_thread_pool_.get() : parallel_thread_pool_.get();
+    size_t verify_thread_count = force_determinism ? 1U : parallel_thread_count_;
+    for (const DexFile* dex_file : dex_files) {
+      CHECK(dex_file != nullptr);
+      VerifyDexFile(jclass_loader,
+                    *dex_file,
+                    verify_thread_pool,
+                    verify_thread_count,
+                    timings);
+    }
   }
 
   if (main_verifier_deps != nullptr) {
@@ -2609,7 +2613,7 @@ class InitializeClassVisitor : public CompilationVisitor {
 void CompilerDriver::InitializeClasses(jobject jni_class_loader,
                                        const DexFile& dex_file,
                                        TimingLogger* timings) {
-  TimingLogger::ScopedTiming t("InitializeNoClinit", timings);
+  TimingLogger::ScopedTiming t("Initialize Classes Dex File", timings);
 
   // Initialization allocates objects and needs to run single-threaded to be deterministic.
   bool force_determinism = GetCompilerOptions().IsForceDeterminism();
@@ -2640,6 +2644,7 @@ void CompilerDriver::InitializeClasses(jobject jni_class_loader,
 void CompilerDriver::InitializeClasses(jobject class_loader,
                                        const std::vector<const DexFile*>& dex_files,
                                        TimingLogger* timings) {
+  TimingLogger::ScopedTiming t("Initialize Classes", timings);
   for (const DexFile* dex_file : dex_files) {
     CHECK(dex_file != nullptr);
     InitializeClasses(class_loader, *dex_file, timings);
@@ -2741,6 +2746,7 @@ static void CompileDexFile(CompilerDriver* driver,
 void CompilerDriver::Compile(jobject class_loader,
                              const std::vector<const DexFile*>& dex_files,
                              TimingLogger* timings) {
+  TimingLogger::ScopedTiming t("Compile Methods", timings);
   if (kDebugProfileGuidedCompilation) {
     const ProfileCompilationInfo* profile_compilation_info =
         GetCompilerOptions().GetProfileCompilationInfo();
diff --git a/dex2oat/linker/oat_writer.cc b/dex2oat/linker/oat_writer.cc
index 7415604ab6..82e7f607ea 100644
--- a/dex2oat/linker/oat_writer.cc
+++ b/dex2oat/linker/oat_writer.cc
@@ -2494,6 +2494,7 @@ void OatWriter::InitBssLayout(InstructionSet instruction_set) {
 }
 
 bool OatWriter::WriteRodata(OutputStream* out) {
+  TimingLogger::ScopedTiming split("WriteRodata", timings_);
   CHECK(write_state_ == WriteState::kWriteRoData);
 
   size_t file_offset = oat_data_offset_;
@@ -2585,6 +2586,7 @@ void OatWriter::WriteVerifierDeps(verifier::VerifierDeps* verifier_deps,
 }
 
 bool OatWriter::WriteCode(OutputStream* out) {
+  TimingLogger::ScopedTiming split("WriteCode", timings_);
   CHECK(write_state_ == WriteState::kWriteText);
 
   // Wrap out to update checksum with each write.
@@ -2621,6 +2623,7 @@ bool OatWriter::WriteCode(OutputStream* out) {
 }
 
 bool OatWriter::WriteDataImgRelRo(OutputStream* out) {
+  TimingLogger::ScopedTiming split("WriteDataImgRelRo", timings_);
   CHECK(write_state_ == WriteState::kWriteDataImgRelRo);
 
   // Wrap out to update checksum with each write.
@@ -2747,6 +2750,8 @@ bool OatWriter::CheckOatSize(OutputStream* out, size_t file_offset, size_t relat
 }
 
 bool OatWriter::WriteHeader(OutputStream* out) {
+  TimingLogger::ScopedTiming split("WriteHeader", timings_);
+
   CHECK(write_state_ == WriteState::kWriteHeader);
 
   // Update checksum with header data.
@@ -3040,7 +3045,6 @@ size_t OatWriter::WriteIndexBssMappingsHelper(OutputStream* out,
 size_t OatWriter::WriteIndexBssMappings(OutputStream* out,
                                         size_t file_offset,
                                         size_t relative_offset) {
-  TimingLogger::ScopedTiming split("WriteMethodBssMappings", timings_);
   if (bss_method_entry_references_.empty() &&
       bss_type_entry_references_.empty() &&
       bss_public_type_entry_references_.empty() &&
@@ -3110,8 +3114,6 @@ size_t OatWriter::WriteIndexBssMappings(OutputStream* out,
 }
 
 size_t OatWriter::WriteOatDexFiles(OutputStream* out, size_t file_offset, size_t relative_offset) {
-  TimingLogger::ScopedTiming split("WriteOatDexFiles", timings_);
-
   for (size_t i = 0, size = oat_dex_files_.size(); i != size; ++i) {
     OatDexFile* oat_dex_file = &oat_dex_files_[i];
     DCHECK_EQ(relative_offset, oat_dex_file->offset_);
@@ -3128,8 +3130,6 @@ size_t OatWriter::WriteOatDexFiles(OutputStream* out, size_t file_offset, size_t
 }
 
 size_t OatWriter::WriteBcpBssInfo(OutputStream* out, size_t file_offset, size_t relative_offset) {
-  TimingLogger::ScopedTiming split("WriteBcpBssInfo", timings_);
-
   const uint32_t number_of_bcp_dexfiles = bcp_bss_info_.size();
   // We skip adding the number of DexFiles if we have no .bss mappings.
   if (number_of_bcp_dexfiles == 0) {