From 70cb09fa676859b0b87a9bdd232b2008f9870498 Mon Sep 17 00:00:00 2001 From: Jacob Lalonde 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 m_launch_or_attach_time; std::optional m_first_private_stop_time; std::optional 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(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 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 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 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 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.