[Lldb-commits] [lldb] [LLDB][Stats] Calculate active time to first Bt (PR #161604)
Jacob Lalonde via lldb-commits
lldb-commits at lists.llvm.org
Wed Oct 1 16:04:20 PDT 2025
https://github.com/Jlalond created https://github.com/llvm/llvm-project/pull/161604
As a part of my recent work on Coredump metrics, I've come up with an 'active time to first bt', where we look at the total time spent loading all the data to get LLDB to report it's first backtrace.
One design decision I'm not settled on is only calculating the load time of the modules in the backtrace, which to my knowledge LLDB would likely try to load all the modules. This may provide us an incorrect result and we may want to instead sum all the module loading times for the entire target and not the thread.
The backtrace command is run under the TargetAPILock (code pasted below) so I gated re-calculating this behind a single bool. Backtrace is not a particularly hot path, so the waste of getting the process sp and the target should be minimal.
```
eCommandRequiresProcess | eCommandRequiresThread |
eCommandTryTargetAPILock | eCommandProcessMustBeLaunched |
eCommandProcessMustBePaused
```
I also discovered #161602 as a part of this testing this patch.
>From 233aaed7db2474e31acf2ecf842d9c0bde70ed4e Mon Sep 17 00:00:00 2001
From: Jacob Lalonde <jalalonde at fb.com>
Date: Wed, 1 Oct 2025 14:50:48 -0700
Subject: [PATCH 1/3] Calculate time to first BT, as a part of my push to
generate better start-up metrics. This calculates all the relevant module
parsing and loading for a given thread to get to the first backtrace,
including the create or load core time.
---
lldb/include/lldb/Target/Statistics.h | 7 ++
.../Python/lldbsuite/test/test_result.py | 9 ++-
lldb/source/Commands/CommandObjectThread.cpp | 2 +
lldb/source/Target/Statistics.cpp | 65 +++++++++++++++++++
.../stats_api/TestStatisticsAPI.py | 51 +++++++++++++++
.../stats_api/arm64-minidump-build-ids.yaml | 26 ++++++++
6 files changed, 155 insertions(+), 5 deletions(-)
create mode 100644 lldb/test/API/functionalities/stats_api/arm64-minidump-build-ids.yaml
diff --git a/lldb/include/lldb/Target/Statistics.h b/lldb/include/lldb/Target/Statistics.h
index d6983bb0b9d24..6ca4c500734c7 100644
--- a/lldb/include/lldb/Target/Statistics.h
+++ b/lldb/include/lldb/Target/Statistics.h
@@ -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);
@@ -328,6 +329,12 @@ 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;
std::optional<StatsTimepoint> m_launch_or_attach_time;
std::optional<StatsTimepoint> m_first_private_stop_time;
std::optional<StatsTimepoint> m_first_public_stop_time;
diff --git a/lldb/packages/Python/lldbsuite/test/test_result.py b/lldb/packages/Python/lldbsuite/test/test_result.py
index 2d574b343b413..58091a111984e 100644
--- a/lldb/packages/Python/lldbsuite/test/test_result.py
+++ b/lldb/packages/Python/lldbsuite/test/test_result.py
@@ -14,9 +14,10 @@
# Third-party modules
import unittest
+from lldbsuite.test_event import build_exception
+
# LLDB Modules
from . import configuration
-from lldbsuite.test_event import build_exception
class LLDBTestResult(unittest.TextTestResult):
@@ -41,8 +42,8 @@ def getTerminalSize():
def ioctl_GWINSZ(fd):
try:
import fcntl
- import termios
import struct
+ import termios
cr = struct.unpack("hh", fcntl.ioctl(fd, termios.TIOCGWINSZ, "1234"))
except:
@@ -160,9 +161,7 @@ def getCategoriesForTest(self, test):
def hardMarkAsSkipped(self, test):
getattr(test, test._testMethodName).__func__.__unittest_skip__ = True
- getattr(
- test, test._testMethodName
- ).__func__.__unittest_skip_why__ = (
+ getattr(test, test._testMethodName).__func__.__unittest_skip_why__ = (
"test case does not fall in any category of interest for this run"
)
diff --git a/lldb/source/Commands/CommandObjectThread.cpp b/lldb/source/Commands/CommandObjectThread.cpp
index bbec714642ec9..f04f8c515a2e4 100644
--- a/lldb/source/Commands/CommandObjectThread.cpp
+++ b/lldb/source/Commands/CommandObjectThread.cpp
@@ -251,6 +251,8 @@ class CommandObjectThreadBacktrace : public CommandObjectIterateOverThreads {
}
}
+ thread->CalculateTarget()->GetStatistics().SetFirstBtTime(thread->CalculateProcess(), *thread);
+
return true;
}
diff --git a/lldb/source/Target/Statistics.cpp b/lldb/source/Target/Statistics.cpp
index 8ad8d507268e2..4842d3dcf8070 100644
--- a/lldb/source/Target/Statistics.cpp
+++ b/lldb/source/Target/Statistics.cpp
@@ -148,6 +148,16 @@ TargetStats::ToJSON(Target &target,
target_metrics_json.try_emplace("targetCreateTime",
m_create_time.get().count());
+ if (m_load_core_time.get().count() > 0) {
+ target_metrics_json.try_emplace("loadCoreTime",
+ m_load_core_time.get().count());
+ }
+
+ if (m_first_bt_time_set) {
+ 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.
@@ -508,6 +518,61 @@ llvm::json::Value DebuggerStats::ReportStatistics(
return std::move(global_stats);
}
+void TargetStats::SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread) {
+ if (m_first_bt_time_set)
+ 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();
+
+ // 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();
+
+ // Lastly, walk over all the symbol locators and add their time.
+ for (const auto &entry : module_sp->GetSymbolLocatorStatistics().map) {
+ elapsed_time += entry.second;
+ }
+ }
+
+ // 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()},
diff --git a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
index f06c9ae14bb7a..79f1dc5afa106 100644
--- a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
+++ b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
@@ -10,6 +10,12 @@
class TestStatsAPI(TestBase):
NO_DEBUG_INFO_TESTCASE = True
+ def get_stats_as_json(self, target):
+ stats = target.GetStatistics()
+ stream = lldb.SBStream()
+ res = stats.GetAsJSON(stream)
+ return json.loads(stream.GetData())
+
def test_stats_api(self):
"""
Test SBTarget::GetStatistics() API.
@@ -27,6 +33,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()
@@ -54,6 +61,17 @@ def test_stats_api(self):
stats_json,
'Make sure the "frameVariable" key in in target.GetStatistics()["targets"][0]',
)
+ self.assertNotIn(
+ "loadCoreTime",
+ 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",
@@ -157,3 +175,36 @@ def test_command_stats_force(self):
stats_force.GetAsJSON(stream_force)
debug_stats_force = json.loads(stream_force.GetData())
self.assertEqual(debug_stats_force["totalDebugInfoByteSize"], 445)
+
+ def test_core_dump_statistics(self):
+ """
+ Test to statistics dump for a postmortem process
+ """
+ yaml_file = "arm64-minidump-build-ids.yaml"
+ src_dir = self.getSourceDir()
+ minidump_path = self.getBuildArtifact(os.path.basename(yaml_file) + ".dmp")
+ self.yaml2obj(os.path.join(src_dir, yaml_file), minidump_path)
+ 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_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 in in target.GetStatistics()["targets"][0]',
+ )
+ self.assertTrue(float(target_stats["activeTimeToFirstBt"]) > 0.0)
diff --git a/lldb/test/API/functionalities/stats_api/arm64-minidump-build-ids.yaml b/lldb/test/API/functionalities/stats_api/arm64-minidump-build-ids.yaml
new file mode 100644
index 0000000000000..883569eae2d5e
--- /dev/null
+++ b/lldb/test/API/functionalities/stats_api/arm64-minidump-build-ids.yaml
@@ -0,0 +1,26 @@
+--- !minidump
+Streams:
+ - Type: SystemInfo
+ Processor Arch: ARM
+ Platform ID: Linux
+ 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
+ Size of Image: 0x00001000
+ Module Name: '/tmp/a'
+ CodeView Record: 4C4570420102030405060708090A0B0C0D0E0F1011121314
+ - Base of Image: 0x0000000000001000
+ Size of Image: 0x00001000
+ Module Name: '/tmp/b'
+ CodeView Record: 4C4570420A141E28323C46505A646E78828C96A0AAB4BEC8
+...
>From 5a41fbd446b612d3ad9391e6d4dbbee348c72e75 Mon Sep 17 00:00:00 2001
From: Jacob Lalonde <jalalonde at fb.com>
Date: Wed, 1 Oct 2025 15:52:05 -0700
Subject: [PATCH 2/3] Run git-clang-format
---
lldb/source/Commands/CommandObjectThread.cpp | 3 ++-
lldb/source/Target/Statistics.cpp | 10 ++++++----
2 files changed, 8 insertions(+), 5 deletions(-)
diff --git a/lldb/source/Commands/CommandObjectThread.cpp b/lldb/source/Commands/CommandObjectThread.cpp
index f04f8c515a2e4..c315973d27b86 100644
--- a/lldb/source/Commands/CommandObjectThread.cpp
+++ b/lldb/source/Commands/CommandObjectThread.cpp
@@ -251,7 +251,8 @@ class CommandObjectThreadBacktrace : public CommandObjectIterateOverThreads {
}
}
- thread->CalculateTarget()->GetStatistics().SetFirstBtTime(thread->CalculateProcess(), *thread);
+ thread->CalculateTarget()->GetStatistics().SetFirstBtTime(
+ thread->CalculateProcess(), *thread);
return true;
}
diff --git a/lldb/source/Target/Statistics.cpp b/lldb/source/Target/Statistics.cpp
index 4842d3dcf8070..29e141a58f51f 100644
--- a/lldb/source/Target/Statistics.cpp
+++ b/lldb/source/Target/Statistics.cpp
@@ -523,8 +523,8 @@ void TargetStats::SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread) {
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.
+ // 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
@@ -534,7 +534,8 @@ void TargetStats::SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread) {
if (!frame_sp)
continue;
- lldb::ModuleSP module_sp = frame_sp->GetSymbolContext(lldb::eSymbolContextModule).module_sp;
+ lldb::ModuleSP module_sp =
+ frame_sp->GetSymbolContext(lldb::eSymbolContextModule).module_sp;
if (!module_sp)
continue;
@@ -543,7 +544,8 @@ void TargetStats::SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread) {
elapsed_time += module_sp->GetSymtabParseTime().get().count();
// 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.
+ // 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;
>From 324ebcf5cbdff779b5c72f3aab8df2ff49a7010b Mon Sep 17 00:00:00 2001
From: Jacob Lalonde <jalalonde at fb.com>
Date: Wed, 1 Oct 2025 15:57:11 -0700
Subject: [PATCH 3/3] Cleanup the unused method and fix some rogue formatter
changes from debugging
---
lldb/packages/Python/lldbsuite/test/test_result.py | 9 +++++----
.../API/functionalities/stats_api/TestStatisticsAPI.py | 6 ------
2 files changed, 5 insertions(+), 10 deletions(-)
diff --git a/lldb/packages/Python/lldbsuite/test/test_result.py b/lldb/packages/Python/lldbsuite/test/test_result.py
index 58091a111984e..2d574b343b413 100644
--- a/lldb/packages/Python/lldbsuite/test/test_result.py
+++ b/lldb/packages/Python/lldbsuite/test/test_result.py
@@ -14,10 +14,9 @@
# Third-party modules
import unittest
-from lldbsuite.test_event import build_exception
-
# LLDB Modules
from . import configuration
+from lldbsuite.test_event import build_exception
class LLDBTestResult(unittest.TextTestResult):
@@ -42,8 +41,8 @@ def getTerminalSize():
def ioctl_GWINSZ(fd):
try:
import fcntl
- import struct
import termios
+ import struct
cr = struct.unpack("hh", fcntl.ioctl(fd, termios.TIOCGWINSZ, "1234"))
except:
@@ -161,7 +160,9 @@ def getCategoriesForTest(self, test):
def hardMarkAsSkipped(self, test):
getattr(test, test._testMethodName).__func__.__unittest_skip__ = True
- getattr(test, test._testMethodName).__func__.__unittest_skip_why__ = (
+ getattr(
+ test, test._testMethodName
+ ).__func__.__unittest_skip_why__ = (
"test case does not fall in any category of interest for this run"
)
diff --git a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
index 79f1dc5afa106..e7c7f7ef3b68a 100644
--- a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
+++ b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
@@ -10,12 +10,6 @@
class TestStatsAPI(TestBase):
NO_DEBUG_INFO_TESTCASE = True
- def get_stats_as_json(self, target):
- stats = target.GetStatistics()
- stream = lldb.SBStream()
- res = stats.GetAsJSON(stream)
- return json.loads(stream.GetData())
-
def test_stats_api(self):
"""
Test SBTarget::GetStatistics() API.
More information about the lldb-commits
mailing list