[lldb] Reduce the frequency of DWARF index progress reporting #118953
Conversation
Indexing a single DWARF unit is a relatively fast operation, particularly if it's a type unit, which can be very small. Reporting progress takes a mutex (and allocates memory, etc.), which creates a lot of contention and slows down indexing noticeably. This patch reports makes us report progress only once per 10 milliseconds (on average), which speeds up indexing by up to 55%. It achieves this by checking whether the time after indexing every unit. This creates the possibility that a particularly large unit could cause us to stop reporting progress for a while (even for units that have already been indexed), but I don't think this is likely to happen, because: - Even the largest units don't take that long to index. The largest unit in lldb (4MB of .debug_info) was indexed in "only" 200ms. - The time is being checked and reported by all worker threads, which means that in order to stall, we'd have to be very unfortunate and pick up an extremely large compile unit on all indexing threads simultaneously. Even if that does happens, the only negative consequence is some jitteriness in a progress bar, which is why I prefer this over alternative implementations which e.g. involve reporting progress from a dedicated thread.
|
@llvm/pr-subscribers-lldb Author: Pavel Labath (labath) ChangesIndexing a single DWARF unit is a relatively fast operation, particularly if it's a type unit, which can be very small. Reporting progress takes a mutex (and allocates memory, etc.), which creates a lot of contention and slows down indexing noticeably. This patch reports makes us report progress only once per 10 milliseconds (on average), which speeds up indexing by up to 55%. It achieves this by checking whether the time after indexing every unit. This creates the possibility that a particularly large unit could cause us to stop reporting progress for a while (even for units that have already been indexed), but I don't think this is likely to happen, because:
Even if that does happens, the only negative consequence is some jitteriness in a progress bar, which is why I prefer this over alternative implementations which e.g. involve reporting progress from a dedicated thread. Full diff: https://github.com/llvm/llvm-project/pull/118953.diff 1 Files Affected:
diff --git a/lldb/source/Plugins/SymbolFile/DWARF/ManualDWARFIndex.cpp b/lldb/source/Plugins/SymbolFile/DWARF/ManualDWARFIndex.cpp
index 5b325e30bef430..a3e595d0194eb9 100644
--- a/lldb/source/Plugins/SymbolFile/DWARF/ManualDWARFIndex.cpp
+++ b/lldb/source/Plugins/SymbolFile/DWARF/ManualDWARFIndex.cpp
@@ -24,6 +24,7 @@
#include "llvm/Support/FormatVariadic.h"
#include "llvm/Support/ThreadPool.h"
#include <atomic>
+#include <chrono>
#include <optional>
using namespace lldb_private;
@@ -91,14 +92,27 @@ void ManualDWARFIndex::Index() {
// are available. This is significantly faster than submiting a new task for
// each unit.
auto for_each_unit = [&](auto &&fn) {
- std::atomic<size_t> next_cu_idx = 0;
- auto wrapper = [&fn, &next_cu_idx, &units_to_index,
- &progress](size_t worker_id) {
- size_t cu_idx;
- while ((cu_idx = next_cu_idx.fetch_add(1, std::memory_order_relaxed)) <
- units_to_index.size()) {
- fn(worker_id, cu_idx, units_to_index[cu_idx]);
- progress.Increment();
+ std::atomic<size_t> next_unit_idx = 0;
+ std::atomic<size_t> units_indexed = 0;
+ auto wrapper = [&fn, &next_unit_idx, &units_indexed, &units_to_index,
+ &progress, num_threads](size_t worker_id) {
+ constexpr auto progress_interval = std::chrono::milliseconds(10);
+
+ // Stagger the reports for different threads so we get a steady stream of
+ // one report per ~10ms.
+ auto next_report = std::chrono::steady_clock::now() +
+ progress_interval * (1 + worker_id);
+ size_t unit_idx;
+ while ((unit_idx = next_unit_idx.fetch_add(
+ 1, std::memory_order_relaxed)) < units_to_index.size()) {
+ fn(worker_id, unit_idx, units_to_index[unit_idx]);
+
+ units_indexed.fetch_add(1, std::memory_order_acq_rel);
+ if (auto now = std::chrono::steady_clock::now(); now >= next_report) {
+ progress.Increment(
+ units_indexed.exchange(0, std::memory_order_acq_rel));
+ next_report = now + num_threads * progress_interval;
+ }
}
};
@@ -106,6 +120,7 @@ void ManualDWARFIndex::Index() {
task_group.async(wrapper, i);
task_group.wait();
+ progress.Increment(units_indexed.load(std::memory_order_acquire));
};
// Extract dies for all DWARFs unit in parallel. Figure out which units
|
|
I would like to say I would love for this improvement to land :). I have observed that on Windows with a fair number (4K+) of small compile units the progress reporting completely dominates indexing time due to contention (presumably not just in the lock but also the IO layers), to the point that disabling it resulted in very large speedups (an operation which previously took 5s+ now was almost instant). |
There was a problem hiding this comment.
Can we build this feature into the Progress class by calling an accessor? Something like:
Progress progress("Manually indexing DWARF", module_desc.GetData(), total_progress);
progress.SetMinimumNotificationTime(std::chrono::milliseconds(10));
Then any busy progress dialogs can take advantage of this timing feature?
|
And the Progress class can check if the an optional instance variable that contains the minimum time has a value and avoid taking the mutex to keep things faster even when building this into the Progress class? |
That's possible, but there are a couple of caveats:
This is the reason I did not want to make this a general feature, but it's not strong opinion, so if you're find with these trade-offs, I can move the code into the Progress class. I definitely don't want get into the business of managing another thread though. |
|
What is the resolution if we switch to "time since epoch" in an atomic value? Can we use some casting to cast a double back into a uint64_t for storage in an atomic? It would be nice to not require everyone to roll their own timeout if possible by just calling an accessor. I am ok with the caveats if everyone else is. |
That's not a problem. I was referring to the time_point::time_since_epoch() (which returns arbitrary precision), not the unix "seconds since epoch" concept. I've created an alternative implementation in #119377 |
Thanks. I think that in your case we're limited by the speed of console updates rather than the progress mutex. We've gotten similar reports for high ("high") latency ssh connections and unusual console setups, and that's the angle I've started working this from before I realized the it was bottlenecking the parallelism. If you have some time, I'd be grateful if you could test this patch out. The thing want the see is whether this completely resolves your issue or if you still see a difference between disabled&enabled progress reports. The reason I'm asking that is that I have a prototype which should specifically help with the slow console issue, and I'm wondering if that is necessary, or if this patch is sufficient. |
or the other patch (#119377). Either is fine for the thing I want to see. |
Agreed.
I can confirm it does! Without the patch, I see a ~25x slowdown when enabling progress reporting ("LLDB time" goes from < 1 second to ~20 seconds), with this patch, the difference is not measurable. |
|
That's great. Thanks for checking this out. Closing this patch in favor of #119377. |
Indexing a single DWARF unit is a relatively fast operation, particularly if it's a type unit, which can be very small. Reporting progress takes a mutex (and allocates memory, etc.), which creates a lot of contention and slows down indexing noticeably.
This patch reports makes us report progress only once per 10 milliseconds (on average), which speeds up indexing by up to 55%. It achieves this by checking whether the time after indexing every unit. This creates the possibility that a particularly large unit could cause us to stop reporting progress for a while (even for units that have already been indexed), but I don't think this is likely to happen, because:
Even if that does happens, the only negative consequence is some jitteriness in a progress bar, which is why I prefer this over alternative implementations which e.g. involve reporting progress from a dedicated thread.