llvmbot wrote:
<!--LLVM PR SUMMARY COMMENT-->
@llvm/pr-subscribers-lldb
Author: Jacob Lalonde (Jlalond)
<details>
<summary>Changes</summary>
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.
---
Full diff: https://github.com/llvm/llvm-project/pull/161604.diff
5 Files Affected:
- (modified) lldb/include/lldb/Target/Statistics.h (+6)
- (modified) lldb/source/Commands/CommandObjectThread.cpp (+3)
- (modified) lldb/source/Target/Statistics.cpp (+62)
- (modified) lldb/test/API/functionalities/stats_api/TestStatisticsAPI.py
(+23-4)
- (modified)
lldb/test/API/functionalities/stats_api/arm64-minidump-build-ids.yaml (+7)
``````````diff
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/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..29e141a58f51f 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,63 @@ 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..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
``````````
</details>
https://github.com/llvm/llvm-project/pull/161604
_______________________________________________
lldb-commits mailing list
[email protected]
https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-commits
