Add locate time for each module in statistics

Author: George Hu

lldb/include/lldb/Symbol/ObjectFile.h

@@ -13,6 +13,7 @@
 #include "lldb/Core/PluginInterface.h"
 #include "lldb/Symbol/Symtab.h"
 #include "lldb/Symbol/UnwindTable.h"
+#include "lldb/Target/Statistics.h"
 #include "lldb/Utility/AddressableBits.h"
 #include "lldb/Utility/DataExtractor.h"
 #include "lldb/Utility/Endian.h"
@@ -589,6 +590,8 @@ class ObjectFile : public std::enable_shared_from_this<ObjectFile>,
   /// this routine to set eTypeDebugInfo when loading debug link files.
   virtual void SetType(Type type) { m_type = type; }
 
+  virtual StatsDuration &GetLocateTime() { return m_locate_time; }
+
   /// The object file should be able to calculate the strata of the object
   /// file.
   ///
@@ -752,6 +755,7 @@ class ObjectFile : public std::enable_shared_from_this<ObjectFile>,
 
 protected:
   // Member variables.
+  StatsDuration m_locate_time; ///< Time to locate the object file
   FileSpec m_file;
   Type m_type;
   Strata m_strata;

lldb/include/lldb/Symbol/SymbolFile.h

@@ -422,6 +422,11 @@ class SymbolFile : public PluginInterface {
   /// hasn't been indexed yet, or a valid duration if it has.
   virtual StatsDuration::Duration GetDebugInfoIndexTime() { return {}; }
 
+  /// Return the time it took to locate any extra symbol files.
+  ///
+  /// \returns 0.0 if no extra symbol files need to be located
+  virtual StatsDuration::Duration GetSymbolLocateTime() { return {}; }
+
   /// Reset the statistics for the symbol file.
   virtual void ResetStatistics() {}
 

lldb/include/lldb/Target/Statistics.h

@@ -122,6 +122,7 @@ struct ModuleStats {
   double symtab_index_time = 0.0;
   double debug_parse_time = 0.0;
   double debug_index_time = 0.0;
+  double symbol_locate_time = 0.0;
   uint64_t debug_info_size = 0;
   bool symtab_loaded_from_cache = false;
   bool symtab_saved_to_cache = false;

lldb/source/Core/ModuleList.cpp

@@ -917,9 +917,13 @@ ModuleList::GetSharedModule(const ModuleSpec &module_spec, ModuleSP &module_sp,
 
   // Fixup the incoming path in case the path points to a valid file, yet the
   // arch or UUID (if one was passed in) don't match.
-  ModuleSpec located_binary_modulespec =
-      PluginManager::LocateExecutableObjectFile(module_spec);
-
+  ModuleSpec located_binary_modulespec;
+  StatsDuration locate_duration;
+  {
+    ElapsedTime elapsed(locate_duration);
+    located_binary_modulespec =
+        PluginManager::LocateExecutableObjectFile(module_spec);
+  }
   // Don't look for the file if it appears to be the same one we already
   // checked for above...
   if (located_binary_modulespec.GetFileSpec() != module_file_spec) {
@@ -992,6 +996,7 @@ ModuleList::GetSharedModule(const ModuleSpec &module_spec, ModuleSP &module_sp,
       // By getting the object file we can guarantee that the architecture
       // matches
       if (module_sp && module_sp->GetObjectFile()) {
+        module_sp->GetObjectFile()->GetLocateTime() += locate_duration;
         if (module_sp->GetObjectFile()->GetType() ==
             ObjectFile::eTypeStubLibrary) {
           module_sp.reset();

lldb/source/Plugins/SymbolFile/DWARF/SymbolFileDWARF.cpp

@@ -4250,11 +4250,13 @@ const std::shared_ptr<SymbolFileDWARFDwo> &SymbolFileDWARF::GetDwpSymbolFile() {
     ModuleSpec module_spec;
     module_spec.GetFileSpec() = m_objfile_sp->GetFileSpec();
     FileSpec dwp_filespec;
+    StatsDuration duration;
     for (const auto &symfile : symfiles.files()) {
       module_spec.GetSymbolFileSpec() =
           FileSpec(symfile.GetPath() + ".dwp", symfile.GetPathStyle());
       LLDB_LOG(log, "Searching for DWP using: \"{0}\"",
                module_spec.GetSymbolFileSpec());
+      ElapsedTime elapsed(duration);
       dwp_filespec =
           PluginManager::LocateExecutableSymbolFile(module_spec, search_paths);
       if (FileSystem::Instance().Exists(dwp_filespec)) {
@@ -4267,6 +4269,8 @@ const std::shared_ptr<SymbolFileDWARFDwo> &SymbolFileDWARF::GetDwpSymbolFile() {
       // find the correct DWP file, as the Debuginfod plugin uses *only* this
       // data to correctly match the DWP file with the binary.
       module_spec.GetUUID() = m_objfile_sp->GetUUID();
+      duration.reset();
+      ElapsedTime elapsed(duration);
       dwp_filespec =
           PluginManager::LocateExecutableSymbolFile(module_spec, search_paths);
     }
@@ -4279,6 +4283,7 @@ const std::shared_ptr<SymbolFileDWARFDwo> &SymbolFileDWARF::GetDwpSymbolFile() {
           FileSystem::Instance().GetByteSize(dwp_filespec), dwp_file_data_sp,
           dwp_file_data_offset);
       if (dwp_obj_file) {
+        dwp_obj_file->GetLocateTime() += duration;
         m_dwp_symfile = std::make_shared<SymbolFileDWARFDwo>(
             *this, dwp_obj_file, DIERef::k_file_index_mask);
       }
@@ -4349,6 +4354,14 @@ LanguageType SymbolFileDWARF::GetLanguageFamily(DWARFUnit &unit) {
   return LanguageTypeFromDWARF(lang);
 }
 
+StatsDuration::Duration SymbolFileDWARF::GetSymbolLocateTime() {
+  StatsDuration total_time;
+  total_time += GetObjectFile()->GetLocateTime();
+  if (m_dwp_symfile)
+    total_time += m_dwp_symfile->GetObjectFile()->GetLocateTime();
+  return total_time;
+}
+
 StatsDuration::Duration SymbolFileDWARF::GetDebugInfoIndexTime() {
   if (m_index)
     return m_index->GetIndexTime();

lldb/source/Plugins/SymbolFile/DWARF/SymbolFileDWARF.h

@@ -309,6 +309,9 @@ class SymbolFileDWARF : public SymbolFileCommon {
   StatsDuration::Duration GetDebugInfoParseTime() override {
     return m_parse_time;
   }
+
+  StatsDuration::Duration GetSymbolLocateTime() override;
+
   StatsDuration::Duration GetDebugInfoIndexTime() override;
 
   StatsDuration &GetDebugInfoParseTimeRef() { return m_parse_time; }

lldb/source/Plugins/SymbolVendor/ELF/SymbolVendorELF.cpp

@@ -103,14 +103,23 @@ SymbolVendorELF::CreateInstance(const lldb::ModuleSP &module_sp,
   module_spec.GetSymbolFileSpec() = fspec;
   module_spec.GetUUID() = uuid;
   FileSpecList search_paths = Target::GetDefaultDebugFileSearchPaths();
-  FileSpec dsym_fspec =
-      PluginManager::LocateExecutableSymbolFile(module_spec, search_paths);
+  StatsDuration duration;
+  FileSpec dsym_fspec;
+  {
+    ElapsedTime elapsed(duration);
+    dsym_fspec =
+        PluginManager::LocateExecutableSymbolFile(module_spec, search_paths);
+  }
   if (!dsym_fspec || IsDwpSymbolFile(module_sp, dsym_fspec)) {
     // If we have a stripped binary or if we have a DWP file, SymbolLocator
     // plugins may be able to give us an unstripped binary or an
     // 'only-keep-debug' stripped file.
-    ModuleSpec unstripped_spec =
-        PluginManager::LocateExecutableObjectFile(module_spec);
+    ModuleSpec unstripped_spec;
+    duration.reset();
+    {
+      ElapsedTime elapsed(duration);
+      unstripped_spec = PluginManager::LocateExecutableObjectFile(module_spec);
+    }
     if (!unstripped_spec)
       return nullptr;
     // The default SymbolLocator plugin returns the original binary if no other
@@ -128,6 +137,7 @@ SymbolVendorELF::CreateInstance(const lldb::ModuleSP &module_sp,
   if (!dsym_objfile_sp)
     return nullptr;
 
+  dsym_objfile_sp->GetLocateTime() += duration;
   // This objfile is for debugging purposes. Sadly, ObjectFileELF won't
   // be able to figure this out consistently as the symbol file may not
   // have stripped the code sections, etc.

lldb/source/Target/Statistics.cpp

@@ -71,6 +71,7 @@ json::Value ModuleStats::ToJSON() const {
   module.try_emplace("debugInfoHadIncompleteTypes",
                      debug_info_had_incomplete_types);
   module.try_emplace("symbolTableStripped", symtab_stripped);
+  module.try_emplace("symbolLocateTime", symbol_locate_time);
   if (!symfile_path.empty())
     module.try_emplace("symbolFilePath", symfile_path);
 
@@ -288,6 +289,7 @@ llvm::json::Value DebuggerStats::ReportStatistics(
 
   json::Array json_targets;
   json::Array json_modules;
+  double symbol_locate_time = 0.0;
   double symtab_parse_time = 0.0;
   double symtab_index_time = 0.0;
   double debug_parse_time = 0.0;
@@ -345,6 +347,10 @@ llvm::json::Value DebuggerStats::ReportStatistics(
         ++debug_index_saved;
       module_stat.debug_index_time = sym_file->GetDebugInfoIndexTime().count();
       module_stat.debug_parse_time = sym_file->GetDebugInfoParseTime().count();
+      module_stat.symbol_locate_time += sym_file->GetSymbolLocateTime().count();
+      if (sym_file->GetObjectFile() != module->GetObjectFile())
+        module_stat.symbol_locate_time +=
+            module->GetObjectFile()->GetLocateTime().get().count();
       module_stat.debug_info_size =
           sym_file->GetDebugInfoSize(load_all_debug_info);
       module_stat.symtab_stripped = module->GetObjectFile()->IsStripped();
@@ -361,6 +367,7 @@ llvm::json::Value DebuggerStats::ReportStatistics(
       if (module_stat.debug_info_had_variable_errors)
         ++num_modules_with_variable_errors;
     }
+    symbol_locate_time += module_stat.symbol_locate_time;
     symtab_parse_time += module_stat.symtab_parse_time;
     symtab_index_time += module_stat.symtab_index_time;
     debug_parse_time += module_stat.debug_parse_time;
@@ -391,6 +398,7 @@ llvm::json::Value DebuggerStats::ReportStatistics(
   }
 
   json::Object global_stats{
+      {"totalSymbolLocateTime", symbol_locate_time},
       {"totalSymbolTableParseTime", symtab_parse_time},
       {"totalSymbolTableIndexTime", symtab_index_time},
       {"totalSymbolTablesLoadedFromCache", symtabs_loaded},