clayborg created this revision. clayborg added reviewers: JDevlieghere, labath, wallace, aadsm, jdoerfert. Herald added a subscriber: emaste. clayborg requested review of this revision. Herald added subscribers: lldb-commits, MaskRay. Herald added a project: LLDB.
The new module stats adds the ability to measure the time it takes to parse and index the symbol tables for each module, and reports modules statistics in the output of "statistics dump" along with the path, UUID and triple of the module. The time it takes to parse and index the symbol tables are also aggregated into new top level key/value pairs at the target level. Repository: rG LLVM Github Monorepo https://reviews.llvm.org/D112279 Files: lldb/include/lldb/Core/Module.h lldb/include/lldb/Target/Statistics.h lldb/source/Plugins/ObjectFile/ELF/ObjectFileELF.cpp lldb/source/Plugins/ObjectFile/JIT/ObjectFileJIT.cpp lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp lldb/source/Plugins/ObjectFile/PECOFF/ObjectFilePECOFF.cpp lldb/source/Symbol/Symtab.cpp lldb/source/Target/Statistics.cpp lldb/source/Target/Target.cpp lldb/test/API/commands/statistics/basic/TestStats.py
Index: lldb/test/API/commands/statistics/basic/TestStats.py =================================================================== --- lldb/test/API/commands/statistics/basic/TestStats.py +++ lldb/test/API/commands/statistics/basic/TestStats.py @@ -139,7 +139,10 @@ keys_exist = [ 'expressionEvaluation', 'frameVariable', + 'modules', 'targetCreateTime', + 'totalSymbolTableParseTime', + 'totalSymbolTableIndexTime' ] keys_missing = [ 'firstStopTime', @@ -181,9 +184,69 @@ 'firstStopTime', 'frameVariable', 'launchOrAttachTime', + 'modules', 'targetCreateTime', + 'totalSymbolTableParseTime', + 'totalSymbolTableIndexTime' ] self.verify_keys(stats, '"stats"', keys_exist, None) self.assertGreater(stats['firstStopTime'], 0.0) self.assertGreater(stats['launchOrAttachTime'], 0.0) self.assertGreater(stats['targetCreateTime'], 0.0) + + def find_module_in_metrics(self, path, stats): + modules = stats['modules'] + for module in modules: + if module['path'] == path: + return module + return None + + def test_modules(self): + """Test "statistics dump --modules" + + Output expected to be something like: + + (lldb) statistics dump --modules + { + "targetCreateTime": 0.26566899599999999, + "totalSymbolTableIndexTime": 0.056834488000000009, + "totalSymbolTableParseTime": 0.093979421999999979, + "modules": [ + { + "path": "/.../TestStats.test_modules/a.out", + "symbolTableIndexTime": 2.3816e-05, + "symbolTableParseTime": 0.000163747, + "triple": "x86_64-apple-macosx11.0.0", + "uuid": "10531B95-4DF4-3FFE-9D51-549DD17435E2" + }, + { + "path": "/.../TestStats.test_modules/libload_a.dylib", + "symbolTableIndexTime": 2.7852999999999999e-05, + "symbolTableParseTime": 0.000110246, + "triple": "x86_64-apple-macosx11.0.0", + "uuid": "F0974CDE-309A-3837-9593-385ABDC93803" + }, + ] + } + + """ + exe = self.getBuildArtifact("a.out") + target = self.createTestTarget(file_path=exe) + stats = self.get_stats(log_path="/tmp/test_default_no_run.txt") + keys_exist = [ + 'targetCreateTime', + 'totalSymbolTableIndexTime', + 'totalSymbolTableParseTime', + 'modules', + ] + self.verify_keys(stats, '"stats"', keys_exist, None) + exe_module = self.find_module_in_metrics(exe, stats) + module_keys = [ + 'path', + 'symbolTableIndexTime', + 'symbolTableParseTime', + 'triple', + 'uuid', + ] + self.assertNotEqual(exe_module, None) + self.verify_keys(exe_module, 'module dict for "%s"' % (exe), module_keys) Index: lldb/source/Target/Target.cpp =================================================================== --- lldb/source/Target/Target.cpp +++ lldb/source/Target/Target.cpp @@ -4454,4 +4454,4 @@ } /// Get metrics associated with this target in JSON format. -llvm::json::Value Target::ReportStatistics() { return m_stats.ToJSON(); } +llvm::json::Value Target::ReportStatistics() { return m_stats.ToJSON(*this); } Index: lldb/source/Target/Statistics.cpp =================================================================== --- lldb/source/Target/Statistics.cpp +++ lldb/source/Target/Statistics.cpp @@ -17,6 +17,16 @@ using namespace lldb_private; using namespace llvm; +static void EmplaceSafeString(llvm::json::Object &obj, llvm::StringRef key, + const std::string &str) { + if (str.empty()) + return; + if (LLVM_LIKELY(llvm::json::isUTF8(str))) + obj.try_emplace(key, str); + else + obj.try_emplace(key, llvm::json::fixUTF8(str)); +} + json::Value StatsSuccessFail::ToJSON() const { return json::Object{{"successes", successes}, {"failures", failures}}; } @@ -26,9 +36,49 @@ return elapsed.count(); } -json::Value TargetStats::ToJSON() { - json::Object target_metrics_json{{m_expr_eval.name, m_expr_eval.ToJSON()}, - {m_frame_var.name, m_frame_var.ToJSON()}}; +void TargetStats::CollectStats(Target &target) { + m_modules.clear(); + for (ModuleSP module_sp : target.GetImages().Modules()) { + ModuleStats module; + module.path = module_sp->GetFileSpec().GetPath(); + module.uuid = module_sp->GetUUID().GetAsString(); + module.triple = module_sp->GetArchitecture().GetTriple().str(); + module.symtab_parse_time = module_sp->GetSymtabParseTime().count(); + module.symtab_index_time = module_sp->GetSymtabIndexTime().count(); + m_modules.push_back(std::move(module)); + } +} + +json::Value ModuleStats::ToJSON() const { + json::Object module; + EmplaceSafeString(module, "path", path); + EmplaceSafeString(module, "uuid", uuid); + EmplaceSafeString(module, "triple", triple); + module.try_emplace("symbolTableParseTime", symtab_parse_time); + module.try_emplace("symbolTableIndexTime", symtab_index_time); + return module; +} + +json::Value TargetStats::ToJSON(Target &target) { + CollectStats(target); + double symtab_parse_time = 0.0; + double symtab_index_time = 0.0; + + json::Array modules; + for (const auto &module : m_modules) { + modules.push_back(module.ToJSON()); + symtab_parse_time += module.symtab_parse_time; + symtab_index_time += module.symtab_index_time; + } + + json::Object target_metrics_json{ + {m_expr_eval.name, m_expr_eval.ToJSON()}, + {m_frame_var.name, m_frame_var.ToJSON()}, + {"totalSymbolTableParseTime", symtab_parse_time}, + {"totalSymbolTableIndexTime", symtab_index_time}, + {"modules", std::move(modules)} + }; + if (m_launch_or_attach_time && m_first_private_stop_time) { double elapsed_time = elapsed(*m_launch_or_attach_time, *m_first_private_stop_time); Index: lldb/source/Symbol/Symtab.cpp =================================================================== --- lldb/source/Symbol/Symtab.cpp +++ lldb/source/Symbol/Symtab.cpp @@ -265,6 +265,7 @@ // Protected function, no need to lock mutex... if (!m_name_indexes_computed) { m_name_indexes_computed = true; + ElapsedTime elapsed(m_objfile->GetModule()->GetSymtabIndexTime()); LLDB_SCOPED_TIMER(); // Collect all loaded language plugins. Index: lldb/source/Plugins/ObjectFile/PECOFF/ObjectFilePECOFF.cpp =================================================================== --- lldb/source/Plugins/ObjectFile/PECOFF/ObjectFilePECOFF.cpp +++ lldb/source/Plugins/ObjectFile/PECOFF/ObjectFilePECOFF.cpp @@ -595,6 +595,7 @@ if (module_sp) { std::lock_guard<std::recursive_mutex> guard(module_sp->GetMutex()); if (m_symtab_up == nullptr) { + ElapsedTime elapsed(module_sp->GetSymtabParseTime()); SectionList *sect_list = GetSectionList(); m_symtab_up = std::make_unique<Symtab>(this); std::lock_guard<std::recursive_mutex> guard(m_symtab_up->GetMutex()); Index: lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp =================================================================== --- lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp +++ lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp @@ -1316,6 +1316,7 @@ if (module_sp) { std::lock_guard<std::recursive_mutex> guard(module_sp->GetMutex()); if (m_symtab_up == nullptr) { + ElapsedTime elapsed(module_sp->GetSymtabParseTime()); m_symtab_up = std::make_unique<Symtab>(this); std::lock_guard<std::recursive_mutex> symtab_guard( m_symtab_up->GetMutex()); Index: lldb/source/Plugins/ObjectFile/JIT/ObjectFileJIT.cpp =================================================================== --- lldb/source/Plugins/ObjectFile/JIT/ObjectFileJIT.cpp +++ lldb/source/Plugins/ObjectFile/JIT/ObjectFileJIT.cpp @@ -111,6 +111,7 @@ if (module_sp) { std::lock_guard<std::recursive_mutex> guard(module_sp->GetMutex()); if (m_symtab_up == nullptr) { + ElapsedTime elapsed(module_sp->GetSymtabParseTime()); m_symtab_up = std::make_unique<Symtab>(this); std::lock_guard<std::recursive_mutex> symtab_guard( m_symtab_up->GetMutex()); Index: lldb/source/Plugins/ObjectFile/ELF/ObjectFileELF.cpp =================================================================== --- lldb/source/Plugins/ObjectFile/ELF/ObjectFileELF.cpp +++ lldb/source/Plugins/ObjectFile/ELF/ObjectFileELF.cpp @@ -2692,9 +2692,6 @@ if (!module_sp) return nullptr; - Progress progress(llvm::formatv("Parsing symbol table for {0}", - m_file.GetFilename().AsCString("<Unknown>"))); - // We always want to use the main object file so we (hopefully) only have one // cached copy of our symtab, dynamic sections, etc. ObjectFile *module_obj_file = module_sp->GetObjectFile(); @@ -2702,6 +2699,10 @@ return module_obj_file->GetSymtab(); if (m_symtab_up == nullptr) { + Progress progress( + llvm::formatv("Parsing symbol table for {0}", + m_file.GetFilename().AsCString("<Unknown>"))); + ElapsedTime elapsed(module_sp->GetSymtabParseTime()); SectionList *section_list = module_sp->GetSectionList(); if (!section_list) return nullptr; Index: lldb/include/lldb/Target/Statistics.h =================================================================== --- lldb/include/lldb/Target/Statistics.h +++ lldb/include/lldb/Target/Statistics.h @@ -72,10 +72,21 @@ uint32_t failures = 0; }; +/// A class that represents statistics for a since lldb_private::Module. +struct ModuleStats { + llvm::json::Value ToJSON() const; + + std::string path; + std::string uuid; + std::string triple; + double symtab_parse_time = 0.0; + double symtab_index_time = 0.0; +}; + /// A class that represents statistics for a since lldb_private::Target. class TargetStats { public: - llvm::json::Value ToJSON(); + llvm::json::Value ToJSON(Target &target); void SetLaunchOrAttachTime(); void SetFirstPrivateStopTime(); @@ -92,6 +103,9 @@ llvm::Optional<StatsTimepoint> m_first_public_stop_time; StatsSuccessFail m_expr_eval{"expressionEvaluation"}; StatsSuccessFail m_frame_var{"frameVariable"}; + std::vector<ModuleStats> m_modules; + + void CollectStats(Target &target); }; class DebuggerStats { Index: lldb/include/lldb/Core/Module.h =================================================================== --- lldb/include/lldb/Core/Module.h +++ lldb/include/lldb/Core/Module.h @@ -16,6 +16,7 @@ #include "lldb/Symbol/SymbolContextScope.h" #include "lldb/Symbol/TypeSystem.h" #include "lldb/Target/PathMappingList.h" +#include "lldb/Target/Statistics.h" #include "lldb/Utility/ArchSpec.h" #include "lldb/Utility/ConstString.h" #include "lldb/Utility/FileSpec.h" @@ -870,6 +871,18 @@ /// Update the ArchSpec to a more specific variant. bool MergeArchitecture(const ArchSpec &arch_spec); + /// Accessor for the symbol table parse time metric. + /// + /// The value is returned as a reference to allow it to be updated by the + /// ElapsedTime RAII object. + StatsDuration &GetSymtabParseTime() { return m_symtab_parse_time; } + + /// Accessor for the symbol table index time metric. + /// + /// The value is returned as a reference to allow it to be updated by the + /// ElapsedTime RAII object. + StatsDuration &GetSymtabIndexTime() { return m_symtab_index_time; } + /// \class LookupInfo Module.h "lldb/Core/Module.h" /// A class that encapsulates name lookup information. /// @@ -995,6 +1008,14 @@ mutable bool m_file_has_changed : 1, m_first_file_changed_log : 1; /// See if the module was modified after it /// was initially opened. + /// We store a symbol table parse time duration here because we might have + /// an object file and a symbol file which both have symbol tables. The parse + /// time for the symbol tables can be aggregated here. + StatsDuration m_symtab_parse_time{0.0}; + /// We store a symbol named index time duration here because we might have + /// an object file and a symbol file which both have symbol tables. The parse + /// time for the symbol tables can be aggregated here. + StatsDuration m_symtab_index_time{0.0}; /// Resolve a file or load virtual address. ///
_______________________________________________ lldb-commits mailing list lldb-commits@lists.llvm.org https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-commits