[LLDB][Stats] Calculate active time to first Bt #161604
Conversation
…tart-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.
Jlalond
force-pushed
the
calculate-first-time-to-bt
branch
from
324ebcf to
5b8d4b6
Compare
|
@llvm/pr-subscribers-lldb Author: Jacob Lalonde (Jlalond) ChangesAs 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. 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:
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
|
|
I'm confused why this is "calculating" this, rather than measuring it? |
I biased towards calculating because we're walking the modules and summing everything up. I have no strong preference on the phrase, but I wanted to include 'activeTime' because imagine a hypothetical of a user has a script that loads a core and loads symbols. During which they leave their computer, we want to sum all the different pieces that got us to that first Bt but ignore any idle time where the user isn't inputting commands. Other than that, measure or calculate I'm open to |
| // 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; |
There was a problem hiding this comment.
use a std::once_flag instead of a bool. That will be thread safe
| thread->CalculateTarget()->GetStatistics().SetFirstBtTime( | ||
| thread->CalculateProcess(), *thread); | ||
|
|
There was a problem hiding this comment.
What is this measuring? This will call the SetFirstBtTime and manually do a backtrace? What if the backtrace has already been done via the SB API? Won't this function go really quickly and not give us any real numbers?
| } | ||
|
|
||
| void TargetStats::SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread) { | ||
| if (m_first_bt_time_set) |
There was a problem hiding this comment.
use std::once with the std::once_flag
| m_load_core_time.get().count()); | ||
| } | ||
|
|
||
| if (m_first_bt_time_set) { |
There was a problem hiding this comment.
If we use a std::once_flag for this, we shlud just check if m_active_time_to_first_bt has a non-zero value
lldb/source/Target/Statistics.cpp
Outdated
| elapsed_time += module_sp->GetSymtabParseTime().get().count(); | ||
| elapsed_time += module_sp->GetSymtabParseTime().get().count(); |
There was a problem hiding this comment.
Why are you doing this twice? And also, why are we adding the symbol table parse time for each stack frame? What if we have a stack with 12 frames from the "a.out" module? Why would we keep adding this? Also, if we are doing a re-use dap scenario, or debugging in Xcode which uses lldb-rpc-server then there is no guarantee that the symbol table parsing time would need to be included here if a previous target had already indexes this module.
There was a problem hiding this comment.
Ah, this was an autocomplete that snuck in.
lldb/source/Target/Statistics.cpp
Outdated
| // Lastly, walk over all the symbol locators and add their time. | ||
| for (const auto &entry : module_sp->GetSymbolLocatorStatistics().map) { | ||
| elapsed_time += entry.second; |
There was a problem hiding this comment.
This won't get executed if there is no symbol file as there is a "continue" up on line 551
There was a problem hiding this comment.
I didn't consider the symbol locator may have ran and no symbol was found.
lldb/source/Target/Statistics.cpp
Outdated
| elapsed_time += sym_file->GetDebugInfoParseTime().count(); | ||
| elapsed_time += sym_file->GetDebugInfoIndexTime().count(); |
There was a problem hiding this comment.
Why twice and also why would we re-count the same module's symbol file over and over? If we have 12 frames with a "a.out" module that has debug info, we should only be counting this once for any frame that is first to show up in the backtrace.
| return std::move(global_stats); | ||
| } | ||
|
|
||
| void TargetStats::SetFirstBtTime(lldb::ProcessSP process_sp, Thread &thread) { |
There was a problem hiding this comment.
No need to pass a process into this function, the thread has access to its process if it is needed.
| if (!INTERRUPT_REQUESTED(GetDebugger(), | ||
| "Interrupt skipped extended backtrace")) { | ||
| DoExtendedBacktrace(thread, result); | ||
| } |
There was a problem hiding this comment.
If we do an extended backtrace above, this won't be included in these stats?
I'm not sure if we can calculate the time to first Bt from the statistics, or at least I'm ignorant on how to do it. If we load symbols after the first Bt we would incorrectly calculate the module loading time that it took to get to the first bt |
4 participants
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.
I also discovered #161602 as a part of this testing this patch.