[Lldb-commits] [lldb] [LLDB][Stats] Calculate active time to first Bt (PR #161604)
Jacob Lalonde via lldb-commits
lldb-commits at lists.llvm.org
Tue Oct 7 16:05:53 PDT 2025
https://github.com/Jlalond updated https://github.com/llvm/llvm-project/pull/161604
>From 70cb09fa676859b0b87a9bdd232b2008f9870498 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/5] 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 | 6 ++
.../Python/lldbsuite/test/test_result.py | 9 ++-
lldb/source/Commands/CommandObjectThread.cpp | 2 +
lldb/source/Target/Statistics.cpp | 60 +++++++++++++++++++
.../stats_api/TestStatisticsAPI.py | 31 +++++++++-
.../stats_api/arm64-minidump-build-ids.yaml | 7 +++
6 files changed, 107 insertions(+), 8 deletions(-)
diff --git a/lldb/include/lldb/Target/Statistics.h b/lldb/include/lldb/Target/Statistics.h
index 2653835206ec7..b5e88ac6a1611 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);
@@ -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;
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 f7311a8b24416..4842d3dcf8070 100644
--- a/lldb/source/Target/Statistics.cpp
+++ b/lldb/source/Target/Statistics.cpp
@@ -153,6 +153,11 @@ TargetStats::ToJSON(Target &target,
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.
@@ -513,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 d7249df350fc1..829079156815a 100644
--- a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
+++ b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
@@ -11,6 +11,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.
@@ -28,6 +34,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()
@@ -60,6 +67,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",
@@ -175,6 +188,7 @@ 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)
@@ -182,6 +196,17 @@ def test_core_load_time(self):
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 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
index 4acbc409d8082..883569eae2d5e 100644
--- a/lldb/test/API/functionalities/stats_api/arm64-minidump-build-ids.yaml
+++ b/lldb/test/API/functionalities/stats_api/arm64-minidump-build-ids.yaml
@@ -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
>From 514851ac0b47958f11871f68c1671f7c2f1307f8 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/5] 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 5b8d4b6e17091dcd4463bf6576d77e7faab285cf 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/5] 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 829079156815a..5b3798802aa6c 100644
--- a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
+++ b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
@@ -11,12 +11,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.
>From 9e4841384eb369d7837fcb1c2f0833d5ecb34c6c Mon Sep 17 00:00:00 2001
From: Jacob Lalonde <jalalonde at fb.com>
Date: Thu, 2 Oct 2025 12:50:35 -0700
Subject: [PATCH 4/5] Fix some of my spelling mistakes
---
lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
index 5b3798802aa6c..b5100f0c3f017 100644
--- a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
+++ b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
@@ -49,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",
@@ -201,6 +201,6 @@ def test_core_load_time(self):
self.assertIn(
"activeTimeToFirstBt",
target_stats,
- 'Make sure the "activeTimeToFirstBt" key in in target.GetStatistics()["targets"][0]',
+ 'Make sure the "activeTimeToFirstBt" key is in target.GetStatistics()["targets"][0]',
)
self.assertTrue(float(target_stats["activeTimeToFirstBt"]) > 0.0)
>From 00084e3ff632dea4796a9586fa83a97ba19f49c1 Mon Sep 17 00:00:00 2001
From: Jacob Lalonde <jalalonde at fb.com>
Date: Tue, 7 Oct 2025 16:05:35 -0700
Subject: [PATCH 5/5] change order of operations, and remove the auto-complete
duplicating two lines
---
lldb/source/Target/Statistics.cpp | 13 ++++++-------
1 file changed, 6 insertions(+), 7 deletions(-)
diff --git a/lldb/source/Target/Statistics.cpp b/lldb/source/Target/Statistics.cpp
index 29e141a58f51f..dd3aa345bf386 100644
--- a/lldb/source/Target/Statistics.cpp
+++ b/lldb/source/Target/Statistics.cpp
@@ -541,7 +541,12 @@ void TargetStats::SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread) {
// 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();
+
+ // Walk over all the symbol locators and add their time. A symbol locator
+ // could have been called and no symbol was found.
+ for (const auto &entry : module_sp->GetSymbolLocatorStatistics().map) {
+ elapsed_time += entry.second;
+ }
// 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
@@ -551,12 +556,6 @@ void TargetStats::SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread) {
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.
More information about the lldb-commits
mailing list