From c571988e9d576f78c00e45fc730f68953c45ea3a Mon Sep 17 00:00:00 2001 From: Greg Clayton Date: Thu, 21 Oct 2021 16:01:00 -0700 Subject: [PATCH] Add modules stats into the "statistics dump" command. 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. Differential Revision: https://reviews.llvm.org/D112279 --- lldb/include/lldb/Core/Module.h | 21 ++++ lldb/include/lldb/Target/Statistics.h | 27 ++++- lldb/source/API/SBTarget.cpp | 4 +- lldb/source/Commands/CommandObjectStats.cpp | 13 +-- .../Plugins/ObjectFile/ELF/ObjectFileELF.cpp | 7 +- .../Plugins/ObjectFile/JIT/ObjectFileJIT.cpp | 1 + .../Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp | 1 + .../Plugins/ObjectFile/PECOFF/ObjectFilePECOFF.cpp | 1 + lldb/source/Symbol/Symtab.cpp | 1 + lldb/source/Target/Statistics.cpp | 81 +++++++++++-- lldb/source/Target/Target.cpp | 2 +- .../API/commands/statistics/basic/TestStats.py | 128 +++++++++++++++++---- .../functionalities/stats_api/TestStatisticsAPI.py | 11 +- 13 files changed, 247 insertions(+), 51 deletions(-) diff --git a/lldb/include/lldb/Core/Module.h b/lldb/include/lldb/Core/Module.h index 767f2d2..b80f4fd 100644 --- a/lldb/include/lldb/Core/Module.h +++ b/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 @@ public: /// 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 @@ protected: 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. /// diff --git a/lldb/include/lldb/Target/Statistics.h b/lldb/include/lldb/Target/Statistics.h index dfeefcb..6bfc7a9 100644 --- a/lldb/include/lldb/Target/Statistics.h +++ b/lldb/include/lldb/Target/Statistics.h @@ -72,10 +72,21 @@ struct StatsSuccessFail { uint32_t failures = 0; }; +/// A class that represents statistics for a since lldb_private::Module. +struct ModuleStats { + llvm::json::Value ToJSON() const; + intptr_t identifier; + 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,8 @@ protected: llvm::Optional m_first_public_stop_time; StatsSuccessFail m_expr_eval{"expressionEvaluation"}; StatsSuccessFail m_frame_var{"frameVariable"}; + std::vector m_module_identifiers; + void CollectStats(Target &target); }; class DebuggerStats { @@ -99,11 +112,19 @@ public: static void SetCollectingStats(bool enable) { g_collecting_stats = enable; } static bool GetCollectingStats() { return g_collecting_stats; } - /// Get metrics associated with all targets in a debugger in JSON format. + /// Get metrics associated with one or all targets in a debugger in JSON + /// format. + /// + /// \param debugger + /// The debugger to get the target list from if \a target is NULL. + /// + /// \param target + /// The single target to emit statistics for if non NULL, otherwise dump + /// statistics only for the specified target. /// /// \return /// Returns a JSON value that contains all target metrics. - static llvm::json::Value ReportStatistics(Debugger &debugger); + static llvm::json::Value ReportStatistics(Debugger &debugger, Target *target); protected: // Collecting stats can be set to true to collect stats that are expensive diff --git a/lldb/source/API/SBTarget.cpp b/lldb/source/API/SBTarget.cpp index a605d46..9db5b6d 100644 --- a/lldb/source/API/SBTarget.cpp +++ b/lldb/source/API/SBTarget.cpp @@ -214,7 +214,9 @@ SBStructuredData SBTarget::GetStatistics() { if (!target_sp) return LLDB_RECORD_RESULT(data); std::string json_str = - llvm::formatv("{0:2}", target_sp->ReportStatistics()).str(); + llvm::formatv("{0:2}", + DebuggerStats::ReportStatistics(target_sp->GetDebugger(), + target_sp.get())).str(); data.m_impl_up->SetObjectSP(StructuredData::ParseJSON(json_str)); return LLDB_RECORD_RESULT(data); } diff --git a/lldb/source/Commands/CommandObjectStats.cpp b/lldb/source/Commands/CommandObjectStats.cpp index 70d63af..f32d559 100644 --- a/lldb/source/Commands/CommandObjectStats.cpp +++ b/lldb/source/Commands/CommandObjectStats.cpp @@ -105,13 +105,12 @@ public: protected: bool DoExecute(Args &command, CommandReturnObject &result) override { - if (m_options.m_all_targets) { - result.AppendMessageWithFormatv( - "{0:2}", DebuggerStats::ReportStatistics(GetDebugger())); - } else { - Target &target = m_exe_ctx.GetTargetRef(); - result.AppendMessageWithFormatv("{0:2}", target.ReportStatistics()); - } + Target *target = nullptr; + if (!m_options.m_all_targets) + target = m_exe_ctx.GetTargetPtr(); + + result.AppendMessageWithFormatv( + "{0:2}", DebuggerStats::ReportStatistics(GetDebugger(), target)); result.SetStatus(eReturnStatusSuccessFinishResult); return true; } diff --git a/lldb/source/Plugins/ObjectFile/ELF/ObjectFileELF.cpp b/lldb/source/Plugins/ObjectFile/ELF/ObjectFileELF.cpp index e236875..8e0f228 100644 --- a/lldb/source/Plugins/ObjectFile/ELF/ObjectFileELF.cpp +++ b/lldb/source/Plugins/ObjectFile/ELF/ObjectFileELF.cpp @@ -2692,9 +2692,6 @@ Symtab *ObjectFileELF::GetSymtab() { if (!module_sp) return nullptr; - Progress progress(llvm::formatv("Parsing symbol table for {0}", - m_file.GetFilename().AsCString(""))); - // 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 @@ Symtab *ObjectFileELF::GetSymtab() { return module_obj_file->GetSymtab(); if (m_symtab_up == nullptr) { + Progress progress( + llvm::formatv("Parsing symbol table for {0}", + m_file.GetFilename().AsCString(""))); + ElapsedTime elapsed(module_sp->GetSymtabParseTime()); SectionList *section_list = module_sp->GetSectionList(); if (!section_list) return nullptr; diff --git a/lldb/source/Plugins/ObjectFile/JIT/ObjectFileJIT.cpp b/lldb/source/Plugins/ObjectFile/JIT/ObjectFileJIT.cpp index b4a26bd..bec0099 100644 --- a/lldb/source/Plugins/ObjectFile/JIT/ObjectFileJIT.cpp +++ b/lldb/source/Plugins/ObjectFile/JIT/ObjectFileJIT.cpp @@ -111,6 +111,7 @@ Symtab *ObjectFileJIT::GetSymtab() { if (module_sp) { std::lock_guard guard(module_sp->GetMutex()); if (m_symtab_up == nullptr) { + ElapsedTime elapsed(module_sp->GetSymtabParseTime()); m_symtab_up = std::make_unique(this); std::lock_guard symtab_guard( m_symtab_up->GetMutex()); diff --git a/lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp b/lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp index 839c99c..6d6ad1a 100644 --- a/lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp +++ b/lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp @@ -1316,6 +1316,7 @@ Symtab *ObjectFileMachO::GetSymtab() { if (module_sp) { std::lock_guard guard(module_sp->GetMutex()); if (m_symtab_up == nullptr) { + ElapsedTime elapsed(module_sp->GetSymtabParseTime()); m_symtab_up = std::make_unique(this); std::lock_guard symtab_guard( m_symtab_up->GetMutex()); diff --git a/lldb/source/Plugins/ObjectFile/PECOFF/ObjectFilePECOFF.cpp b/lldb/source/Plugins/ObjectFile/PECOFF/ObjectFilePECOFF.cpp index 1722602..5c7489e 100644 --- a/lldb/source/Plugins/ObjectFile/PECOFF/ObjectFilePECOFF.cpp +++ b/lldb/source/Plugins/ObjectFile/PECOFF/ObjectFilePECOFF.cpp @@ -595,6 +595,7 @@ Symtab *ObjectFilePECOFF::GetSymtab() { if (module_sp) { std::lock_guard guard(module_sp->GetMutex()); if (m_symtab_up == nullptr) { + ElapsedTime elapsed(module_sp->GetSymtabParseTime()); SectionList *sect_list = GetSectionList(); m_symtab_up = std::make_unique(this); std::lock_guard guard(m_symtab_up->GetMutex()); diff --git a/lldb/source/Symbol/Symtab.cpp b/lldb/source/Symbol/Symtab.cpp index 313b451..6100398 100644 --- a/lldb/source/Symbol/Symtab.cpp +++ b/lldb/source/Symbol/Symtab.cpp @@ -265,6 +265,7 @@ void Symtab::InitNameIndexes() { // 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. diff --git a/lldb/source/Target/Statistics.cpp b/lldb/source/Target/Statistics.cpp index ce7a4f2..e1703d7 100644 --- a/lldb/source/Target/Statistics.cpp +++ b/lldb/source/Target/Statistics.cpp @@ -17,6 +17,16 @@ using namespace lldb; 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,35 @@ static double elapsed(const StatsTimepoint &start, const StatsTimepoint &end) { 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_module_identifiers.clear(); + for (ModuleSP module_sp : target.GetImages().Modules()) + m_module_identifiers.emplace_back((intptr_t)module_sp.get()); +} + +json::Value ModuleStats::ToJSON() const { + json::Object module; + EmplaceSafeString(module, "path", path); + EmplaceSafeString(module, "uuid", uuid); + EmplaceSafeString(module, "triple", triple); + module.try_emplace("identifier", identifier); + module.try_emplace("symbolTableParseTime", symtab_parse_time); + module.try_emplace("symbolTableIndexTime", symtab_index_time); + return module; +} + +json::Value TargetStats::ToJSON(Target &target) { + CollectStats(target); + + json::Array json_module_uuid_array; + for (auto module_identifier : m_module_identifiers) + json_module_uuid_array.emplace_back(module_identifier); + + json::Object target_metrics_json{ + {m_expr_eval.name, m_expr_eval.ToJSON()}, + {m_frame_var.name, m_frame_var.ToJSON()}, + {"moduleIdentifiers", std::move(json_module_uuid_array)}}; + 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); @@ -67,13 +103,42 @@ void TargetStats::SetFirstPublicStopTime() { bool DebuggerStats::g_collecting_stats = false; -llvm::json::Value DebuggerStats::ReportStatistics(Debugger &debugger) { - json::Array targets; - for (const auto &target : debugger.GetTargetList().Targets()) { - targets.emplace_back(target->ReportStatistics()); +llvm::json::Value DebuggerStats::ReportStatistics(Debugger &debugger, + Target *target) { + json::Array json_targets; + json::Array json_modules; + double symtab_parse_time = 0.0; + double symtab_index_time = 0.0; + if (target) { + json_targets.emplace_back(target->ReportStatistics()); + } else { + for (const auto &target : debugger.GetTargetList().Targets()) + json_targets.emplace_back(target->ReportStatistics()); } + std::vector modules; + std::lock_guard guard( + Module::GetAllocationModuleCollectionMutex()); + const size_t num_modules = Module::GetNumberAllocatedModules(); + ModuleSP module_sp; + for (size_t image_idx = 0; image_idx < num_modules; ++image_idx) { + Module *module = Module::GetAllocatedModuleAtIndex(image_idx); + ModuleStats module_stat; + module_stat.identifier = (intptr_t)module; + module_stat.path = module->GetFileSpec().GetPath(); + module_stat.uuid = module->GetUUID().GetAsString(); + module_stat.triple = module->GetArchitecture().GetTriple().str(); + module_stat.symtab_parse_time = module->GetSymtabParseTime().count(); + module_stat.symtab_index_time = module->GetSymtabIndexTime().count(); + symtab_parse_time += module_stat.symtab_parse_time; + symtab_index_time += module_stat.symtab_index_time; + json_modules.emplace_back(module_stat.ToJSON()); + } + json::Object global_stats{ - {"targets", std::move(targets)}, + {"targets", std::move(json_targets)}, + {"modules", std::move(json_modules)}, + {"totalSymbolTableParseTime", symtab_parse_time}, + {"totalSymbolTableIndexTime", symtab_index_time}, }; return std::move(global_stats); } diff --git a/lldb/source/Target/Target.cpp b/lldb/source/Target/Target.cpp index 4917052..2dbb53a 100644 --- a/lldb/source/Target/Target.cpp +++ b/lldb/source/Target/Target.cpp @@ -4454,4 +4454,4 @@ std::recursive_mutex &Target::GetAPIMutex() { } /// 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); } diff --git a/lldb/test/API/commands/statistics/basic/TestStats.py b/lldb/test/API/commands/statistics/basic/TestStats.py index 838b270..eda13c8 100644 --- a/lldb/test/API/commands/statistics/basic/TestStats.py +++ b/lldb/test/API/commands/statistics/basic/TestStats.py @@ -82,12 +82,18 @@ class TestCase(TestBase): f.write(metrics_json) return json.loads(metrics_json) + + def get_target_stats(self, debug_stats): + if "targets" in debug_stats: + return debug_stats["targets"][0] + return None + def test_expressions_frame_var_counts(self): lldbutil.run_to_source_breakpoint(self, "// break here", lldb.SBFileSpec("main.c")) self.expect("expr patatino", substrs=['27']) - stats = self.get_stats() + stats = self.get_target_stats(self.get_stats()) self.verify_success_fail_count(stats, 'expressionEvaluation', 1, 0) self.expect("expr doesnt_exist", error=True, substrs=["undeclared identifier 'doesnt_exist'"]) @@ -103,13 +109,13 @@ class TestCase(TestBase): self.expect("expr -Z 3 -- 1", error=True, substrs=["expression cannot be used with --element-count"]) # We should have gotten 3 new failures and the previous success. - stats = self.get_stats() + stats = self.get_target_stats(self.get_stats()) self.verify_success_fail_count(stats, 'expressionEvaluation', 2, 2) self.expect("statistics enable") # 'frame var' with enabled statistics will change stats. self.expect("frame var", substrs=['27']) - stats = self.get_stats() + stats = self.get_target_stats(self.get_stats()) self.verify_success_fail_count(stats, 'frameVariable', 1, 0) def test_default_no_run(self): @@ -123,22 +129,39 @@ class TestCase(TestBase): (lldb) statistics dump { - "targetCreateTime": 0.26566899599999999, - "expressionEvaluation": { - "failures": 0, - "successes": 0 - }, - "frameVariable": { - "failures": 0, - "successes": 0 - }, + "modules" : [...], + "targets" : [ + { + "targetCreateTime": 0.26566899599999999, + "expressionEvaluation": { + "failures": 0, + "successes": 0 + }, + "frameVariable": { + "failures": 0, + "successes": 0 + }, + "moduleIdentifiers": [...], + } + ], + "totalSymbolTableParseTime": 0.123, + "totalSymbolTableIndexTime": 0.234, } """ target = self.createTestTarget() - stats = self.get_stats() + debug_stats = self.get_stats() + debug_stat_keys = [ + 'modules', + 'targets', + 'totalSymbolTableParseTime', + 'totalSymbolTableIndexTime', + ] + self.verify_keys(debug_stats, '"debug_stats"', debug_stat_keys, None) + stats = debug_stats['targets'][0] keys_exist = [ 'expressionEvaluation', 'frameVariable', + 'moduleIdentifiers', 'targetCreateTime', ] keys_missing = [ @@ -158,32 +181,87 @@ class TestCase(TestBase): (lldb) statistics dump { - "firstStopTime": 0.34164492800000001, - "launchOrAttachTime": 0.31969605400000001, - "targetCreateTime": 0.0040863039999999998 - "expressionEvaluation": { - "failures": 0, - "successes": 0 - }, - "frameVariable": { - "failures": 0, - "successes": 0 - }, + "modules" : [...], + "targets" : [ + { + "firstStopTime": 0.34164492800000001, + "launchOrAttachTime": 0.31969605400000001, + "moduleIdentifiers": [...], + "targetCreateTime": 0.0040863039999999998 + "expressionEvaluation": { + "failures": 0, + "successes": 0 + }, + "frameVariable": { + "failures": 0, + "successes": 0 + }, + } + ], + "totalSymbolTableParseTime": 0.123, + "totalSymbolTableIndexTime": 0.234, } """ target = self.createTestTarget() lldbutil.run_to_source_breakpoint(self, "// break here", lldb.SBFileSpec("main.c")) - stats = self.get_stats() + debug_stats = self.get_stats() + debug_stat_keys = [ + 'modules', + 'targets', + 'totalSymbolTableParseTime', + 'totalSymbolTableIndexTime', + ] + self.verify_keys(debug_stats, '"debug_stats"', debug_stat_keys, None) + stats = debug_stats['targets'][0] keys_exist = [ 'expressionEvaluation', 'firstStopTime', 'frameVariable', 'launchOrAttachTime', + 'moduleIdentifiers', 'targetCreateTime', ] 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" and the module information. + """ + exe = self.getBuildArtifact("a.out") + target = self.createTestTarget(file_path=exe) + debug_stats = self.get_stats() + debug_stat_keys = [ + 'modules', + 'targets', + 'totalSymbolTableParseTime', + 'totalSymbolTableIndexTime', + ] + self.verify_keys(debug_stats, '"debug_stats"', debug_stat_keys, None) + stats = debug_stats['targets'][0] + keys_exist = [ + 'moduleIdentifiers', + ] + self.verify_keys(stats, '"stats"', keys_exist, None) + exe_module = self.find_module_in_metrics(exe, debug_stats) + module_keys = [ + 'identifier', + 'path', + 'symbolTableIndexTime', + 'symbolTableParseTime', + 'triple', + 'uuid', + ] + self.assertNotEqual(exe_module, None) + self.verify_keys(exe_module, 'module dict for "%s"' % (exe), module_keys) diff --git a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py index bbbc073..80e5a4e 100644 --- a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py +++ b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py @@ -28,11 +28,16 @@ class TestStatsAPI(TestBase): stats = target.GetStatistics() stream = lldb.SBStream() res = stats.GetAsJSON(stream) - stats_json = json.loads(stream.GetData()) + debug_stats = json.loads(stream.GetData()) + self.assertEqual('targets' in debug_stats, True, + 'Make sure the "targets" key in in target.GetStatistics()') + self.assertEqual('modules' in debug_stats, True, + 'Make sure the "modules" key in in target.GetStatistics()') + stats_json = debug_stats['targets'][0] self.assertEqual('expressionEvaluation' in stats_json, True, - 'Make sure the "expressionEvaluation" key in in target.GetStatistics()') + 'Make sure the "expressionEvaluation" key in in target.GetStatistics()["targets"][0]') self.assertEqual('frameVariable' in stats_json, True, - 'Make sure the "frameVariable" key in in target.GetStatistics()') + 'Make sure the "frameVariable" key in in target.GetStatistics()["targets"][0]') expressionEvaluation = stats_json['expressionEvaluation'] self.assertEqual('successes' in expressionEvaluation, True, 'Make sure the "successes" key in in "expressionEvaluation" dictionary"') -- 2.7.4