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/source/Commands/CommandObjectThread.cpp b/lldb/source/Commands/CommandObjectThread.cpp index bbec714642ec9..c315973d27b86 100644 --- a/lldb/source/Commands/CommandObjectThread.cpp +++ b/lldb/source/Commands/CommandObjectThread.cpp @@ -251,6 +251,9 @@ 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..dd3aa345bf386 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,62 @@ 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(); + + // 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 + // effects. + SymbolFile *sym_file = module_sp->GetSymbolFile(/*can_create=*/false); + if (!sym_file) + continue; + + elapsed_time += sym_file->GetDebugInfoParseTime().count(); + } + + // 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..b5100f0c3f017 100644 --- a/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py +++ b/lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py @@ -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() @@ -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", @@ -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", @@ -175,6 +182,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 +190,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 is 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