Skip to content

[LLDB][Stats] Calculate active time to first Bt #161604

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 5 commits into
base: main
Choose a base branch
from
Open

[LLDB][Stats] Calculate active time to first Bt #161604

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
70cb09f
Calculate time to first BT, as a part of my push to generate better s…
Jlalond Oct 1, 2025
514851a
Run git-clang-format
Jlalond Oct 1, 2025
5b8d4b6
Cleanup the unused method and fix some rogue formatter changes from d…
Jlalond Oct 1, 2025
9e48413
Fix some of my spelling mistakes
Jlalond Oct 2, 2025
00084e3
change order of operations, and remove the auto-complete duplicating …
Jlalond Oct 7, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions lldb/include/lldb/Target/Statistics.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -317,6 +317,7 @@ class TargetStats {
void SetLaunchOrAttachTime();
void SetFirstPrivateStopTime();
void SetFirstPublicStopTime();
void SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread);
void IncreaseSourceMapDeduceCount();
void IncreaseSourceRealpathAttemptCount(uint32_t count);
void IncreaseSourceRealpathCompatibleCount(uint32_t count);
Expand All @@ -330,6 +331,11 @@ class TargetStats {
protected:
StatsDuration m_create_time;
StatsDuration m_load_core_time;
StatsDuration m_active_time_to_first_bt;
// std::atomic doesn't play well with std::optional
// so add a simple flag, this should only ever be accessed
// by a single thread under the target lock.
bool m_first_bt_time_set = false;
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

use a std::once_flag instead of a bool. That will be thread safe

std::optional<StatsTimepoint> m_launch_or_attach_time;
std::optional<StatsTimepoint> m_first_private_stop_time;
std::optional<StatsTimepoint> m_first_public_stop_time;
Expand Down
3 changes: 3 additions & 0 deletions lldb/source/Commands/CommandObjectThread.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -251,6 +251,9 @@ class CommandObjectThreadBacktrace : public CommandObjectIterateOverThreads {
}
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we do an extended backtrace above, this won't be included in these stats?

}

thread->CalculateTarget()->GetStatistics().SetFirstBtTime(
thread->CalculateProcess(), *thread);

Comment on lines +254 to +256
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What is this measuring? This will call the SetFirstBtTime and manually do a backtrace? What if the backtrace has already been done via the SB API? Won't this function go really quickly and not give us any real numbers?

return true;
}

Expand Down
62 changes: 62 additions & 0 deletions lldb/source/Target/Statistics.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -153,6 +153,11 @@ TargetStats::ToJSON(Target &target,
m_load_core_time.get().count());
}

if (m_first_bt_time_set) {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we use a std::once_flag for this, we shlud just check if m_active_time_to_first_bt has a non-zero value

target_metrics_json.try_emplace("activeTimeToFirstBt",
m_active_time_to_first_bt.get().count());
}

json::Array breakpoints_array;
double totalBreakpointResolveTime = 0.0;
// Report both the normal breakpoint list and the internal breakpoint list.
Expand Down Expand Up @@ -513,6 +518,63 @@ llvm::json::Value DebuggerStats::ReportStatistics(
return std::move(global_stats);
}

void TargetStats::SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread) {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No need to pass a process into this function, the thread has access to its process if it is needed.

if (m_first_bt_time_set)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

use std::once with the std::once_flag

return;

// Our goal here is to calculate the total active time to get to the first bt
// so this will be the target creation time, or the load core time plus all
// the time to load and index modules and their debug info.
double elapsed_time = 0.0;
// GetStackFrameCount can be expensive, but at this point we should
// have completed a BT successfully, so the frames should already
// exist.
for (size_t i = 0; i < thread.GetStackFrameCount(); ++i) {
lldb::StackFrameSP frame_sp = thread.GetStackFrameAtIndex(i);
if (!frame_sp)
continue;

lldb::ModuleSP module_sp =
frame_sp->GetSymbolContext(lldb::eSymbolContextModule).module_sp;
if (!module_sp)
continue;

// Add the time it took to load and index the module.
elapsed_time += module_sp->GetSymtabParseTime().get().count();
elapsed_time += module_sp->GetSymtabParseTime().get().count();
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why are you doing this twice? And also, why are we adding the symbol table parse time for each stack frame? What if we have a stack with 12 frames from the "a.out" module? Why would we keep adding this? Also, if we are doing a re-use dap scenario, or debugging in Xcode which uses lldb-rpc-server then there is no guarantee that the symbol table parsing time would need to be included here if a previous target had already indexes this module.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, this was an autocomplete that snuck in.


// Add the time it took to load and index the debug info. Can create
// false is very important here. We don't want this call to have any side
// effects.
SymbolFile *sym_file = module_sp->GetSymbolFile(/*can_create=*/false);
if (!sym_file)
continue;

elapsed_time += sym_file->GetDebugInfoParseTime().count();
elapsed_time += sym_file->GetDebugInfoIndexTime().count();
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why twice and also why would we re-count the same module's symbol file over and over? If we have 12 frames with a "a.out" module that has debug info, we should only be counting this once for any frame that is first to show up in the backtrace.


// Lastly, walk over all the symbol locators and add their time.
for (const auto &entry : module_sp->GetSymbolLocatorStatistics().map) {
elapsed_time += entry.second;
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This won't get executed if there is no symbol file as there is a "continue" up on line 551

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I didn't consider the symbol locator may have ran and no symbol was found.

}
}

// Process should be valid if we've already generated a backtrace.
assert(process_sp);
m_first_bt_time_set = true;
m_active_time_to_first_bt += std::chrono::duration<double>(elapsed_time);
if (process_sp->IsLiveDebugSession()) {

// If we are in a live debug session, then the target creation time is
// the time it took to load the executable and all the modules.
m_active_time_to_first_bt += m_create_time.get();
} else {
// If we are in a core file, then the target creation time is the time it
// took to load the core file.
m_active_time_to_first_bt += m_load_core_time.get();
}
}

llvm::json::Value SummaryStatistics::ToJSON() const {
return json::Object{{
{"name", GetName()},
Expand Down
27 changes: 23 additions & 4 deletions lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,7 @@ def test_stats_api(self):
self.assertTrue(target.GetCollectingStats())
target.SetCollectingStats(False)
self.assertFalse(target.GetCollectingStats())
self.runCmd("bt")

# Test the function to get the statistics in JSON'ish.
stats = target.GetStatistics()
Expand All @@ -48,7 +49,7 @@ def test_stats_api(self):
self.assertIn(
"expressionEvaluation",
stats_json,
'Make sure the "expressionEvaluation" key in in target.GetStatistics()["targets"][0]',
'Make sure the "expressionEvaluation" key is in target.GetStatistics()["targets"][0]',
)
self.assertIn(
"frameVariable",
Expand All @@ -60,6 +61,12 @@ def test_stats_api(self):
stats_json,
"LoadCoreTime should not be present in a live, non-coredump target",
)
self.assertIn(
"activeTimeToFirstBt",
stats_json,
'Make sure the "activeTimeToFirstBt" key in in target.GetStatistics()["targets"][0]',
)
self.assertTrue(float(stats_json["activeTimeToFirstBt"]) > 0.0)
expressionEvaluation = stats_json["expressionEvaluation"]
self.assertIn(
"successes",
Expand Down Expand Up @@ -175,13 +182,25 @@ def test_core_load_time(self):
target = self.dbg.CreateTarget(None)
process = target.LoadCore(minidump_path)
self.assertTrue(process.IsValid())
self.runCmd("bt")

stats_options = lldb.SBStatisticsOptions()
stats = target.GetStatistics(stats_options)
stream = lldb.SBStream()
stats.GetAsJSON(stream)
debug_stats = json.loads(stream.GetData())
self.assertTrue("targets" in debug_stats)
target_info = debug_stats["targets"][0]
self.assertTrue("loadCoreTime" in target_info)
self.assertTrue(float(target_info["loadCoreTime"]) > 0.0)

target_stats = debug_stats["targets"][0]
self.assertIn(
"loadCoreTime",
target_stats,
"Ensure load core time is present in target statistics",
)
self.assertTrue(float(target_stats["loadCoreTime"]) > 0.0)
self.assertIn(
"activeTimeToFirstBt",
target_stats,
'Make sure the "activeTimeToFirstBt" key is in target.GetStatistics()["targets"][0]',
)
self.assertTrue(float(target_stats["activeTimeToFirstBt"]) > 0.0)
7 changes: 7 additions & 0 deletions lldb/test/API/functionalities/stats_api/arm64-minidump-build-ids.yaml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,13 @@ Streams:
CSD Version: '15E216'
CPU:
CPUID: 0x00000000
- Type: ThreadList
Threads:
- Thread Id: 0x000074DD
Context: 0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000B0010000000000033000000000000000000000002020100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000040109600000000000100000000000000000000000000000068E7D0C8FF7F000068E7D0C8FF7F000097E6D0C8FF7F000010109600000000000000000000000000020000000000000088E4D0C8FF7F0000603FFF85C77F0000F00340000000000080E7D0C8FF7F000000000000000000000000000000000000E0034000000000007F0300000000000000000000000000000000000000000000801F0000FFFF00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF252525252525252525252525252525250000000000000000000000000000000000000000000000000000000000000000FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000FF00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
Stack:
Start of Memory Range: 0x00007FFFC8D0E000
Content: C0FFEEC0FFEEC0FFEEC0FFEEC0FFEEC0FFEEC0FFEEC0FFEE
- Type: ModuleList
Modules:
- Base of Image: 0x0000000000001000
Expand Down
Loading