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
This commit is contained in:
Greg Clayton
2021-10-21 16:01:00 -07:00
parent cdb335ffaf
commit c571988e9d
13 changed files with 247 additions and 51 deletions

View File

@@ -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.
///

View File

@@ -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<StatsTimepoint> m_first_public_stop_time;
StatsSuccessFail m_expr_eval{"expressionEvaluation"};
StatsSuccessFail m_frame_var{"frameVariable"};
std::vector<intptr_t> 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

View File

@@ -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);
}

View File

@@ -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;
}

View File

@@ -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("<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 @@ 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("<Unknown>")));
ElapsedTime elapsed(module_sp->GetSymtabParseTime());
SectionList *section_list = module_sp->GetSectionList();
if (!section_list)
return nullptr;

View File

@@ -111,6 +111,7 @@ Symtab *ObjectFileJIT::GetSymtab() {
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());

View File

@@ -1316,6 +1316,7 @@ Symtab *ObjectFileMachO::GetSymtab() {
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());

View File

@@ -595,6 +595,7 @@ Symtab *ObjectFilePECOFF::GetSymtab() {
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());

View File

@@ -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.

View File

@@ -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<ModuleStats> modules;
std::lock_guard<std::recursive_mutex> 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);
}

View File

@@ -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); }

View File

@@ -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)

View File

@@ -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"')