[WIP] [lldb][Progress] Report progress when completing types from DWARF #91452
Conversation
|
@llvm/pr-subscribers-lldb Author: Michael Buch (Michael137) ChangesThis is an attempt at displaying the work that's being done by LLDB when waiting on type-completion events, e.g., when running an expression. We add three new progress reports (across three commits):
Some remaining questions:
Full diff: https://github.com/llvm/llvm-project/pull/91452.diff 5 Files Affected:
diff --git a/lldb/source/Plugins/ExpressionParser/Clang/ClangASTImporter.cpp b/lldb/source/Plugins/ExpressionParser/Clang/ClangASTImporter.cpp
index 30b50df79da90..cf9f1a2d47922 100644
--- a/lldb/source/Plugins/ExpressionParser/Clang/ClangASTImporter.cpp
+++ b/lldb/source/Plugins/ExpressionParser/Clang/ClangASTImporter.cpp
@@ -7,6 +7,7 @@
//===----------------------------------------------------------------------===//
#include "lldb/Core/Module.h"
+#include "lldb/Core/Progress.h"
#include "lldb/Utility/LLDBAssert.h"
#include "lldb/Utility/LLDBLog.h"
#include "lldb/Utility/Log.h"
@@ -17,6 +18,7 @@
#include "clang/AST/RecordLayout.h"
#include "clang/Sema/Lookup.h"
#include "clang/Sema/Sema.h"
+#include "llvm/ADT/ScopeExit.h"
#include "llvm/Support/raw_ostream.h"
#include "Plugins/ExpressionParser/Clang/ClangASTImporter.h"
@@ -1131,6 +1133,7 @@ ClangASTImporter::ASTImporterDelegate::ImportImpl(Decl *From) {
LLDB_LOG(log, "[ClangASTImporter] Complete definition not found");
}
+ UpdateImportProgress(From);
return ASTImporter::ImportImpl(From);
}
@@ -1411,3 +1414,35 @@ clang::Decl *
ClangASTImporter::ASTImporterDelegate::GetOriginalDecl(clang::Decl *To) {
return m_main.GetDeclOrigin(To).decl;
}
+
+void ClangASTImporter::ASTImporterDelegate::UpdateImportProgress(
+ clang::Decl const *From) {
+ assert(From &&
+ "Trying to report import progress using an invalid clang::Decl.");
+
+ // If we can't determine the decl's name, we don't know what to
+ // update the progress bar with. So bail out.
+ auto const *ND = dyn_cast<NamedDecl>(From);
+ if (!ND)
+ return;
+
+ if (!m_import_progress_up) {
+ auto const *from_ast =
+ TypeSystemClang::GetASTContext(&From->getASTContext());
+ auto const *to_ast = TypeSystemClang::GetASTContext(&getToContext());
+
+ assert(from_ast && to_ast);
+
+ llvm::SmallVector<llvm::StringRef> from_name_parts;
+ llvm::SplitString(from_ast->getDisplayName(), from_name_parts, "/");
+ auto from_name = from_name_parts.back();
+
+ llvm::SmallVector<llvm::StringRef> to_name_parts;
+ llvm::SplitString(to_ast->getDisplayName(), to_name_parts, "/");
+ auto to_name = to_name_parts.back();
+ m_import_progress_up = std::make_unique<Progress>(
+ llvm::formatv("Importing '{0}' to '{1}'", from_name, to_name));
+ }
+
+ m_import_progress_up->Increment(1, ND->getNameAsString());
+}
diff --git a/lldb/source/Plugins/ExpressionParser/Clang/ClangASTImporter.h b/lldb/source/Plugins/ExpressionParser/Clang/ClangASTImporter.h
index bc962e544d2f1..f666d0c0fc52c 100644
--- a/lldb/source/Plugins/ExpressionParser/Clang/ClangASTImporter.h
+++ b/lldb/source/Plugins/ExpressionParser/Clang/ClangASTImporter.h
@@ -22,6 +22,7 @@
#include "clang/Basic/FileManager.h"
#include "clang/Basic/FileSystemOptions.h"
+#include "lldb/Core/Progress.h"
#include "lldb/Host/FileSystem.h"
#include "lldb/Symbol/CompilerDeclContext.h"
#include "lldb/Utility/LLDBAssert.h"
@@ -346,6 +347,8 @@ class ClangASTImporter {
llvm::Expected<clang::Decl *> ImportImpl(clang::Decl *From) override;
private:
+ void UpdateImportProgress(clang::Decl const *From);
+
/// Decls we should ignore when mapping decls back to their original
/// ASTContext. Used by the CxxModuleHandler to mark declarations that
/// were created from the 'std' C++ module to prevent that the Importer
@@ -356,6 +359,7 @@ class ClangASTImporter {
CxxModuleHandler *m_std_handler = nullptr;
/// The currently attached listener.
NewDeclListener *m_new_decl_listener = nullptr;
+ std::unique_ptr<lldb_private::Progress> m_import_progress_up = nullptr;
};
typedef std::shared_ptr<ASTImporterDelegate> ImporterDelegateSP;
diff --git a/lldb/source/Plugins/SymbolFile/DWARF/DWARFASTParserClang.cpp b/lldb/source/Plugins/SymbolFile/DWARF/DWARFASTParserClang.cpp
index f8101aba5c627..605428619d805 100644
--- a/lldb/source/Plugins/SymbolFile/DWARF/DWARFASTParserClang.cpp
+++ b/lldb/source/Plugins/SymbolFile/DWARF/DWARFASTParserClang.cpp
@@ -479,6 +479,8 @@ TypeSP DWARFASTParserClang::ParseTypeFromDWARF(const SymbolContext &sc,
return nullptr;
}
+ UpdateParsingProgress(attrs.name.AsCString("(anonymous)"));
+
if (type_is_new_ptr)
*type_is_new_ptr = true;
@@ -3952,3 +3954,20 @@ void DWARFASTParserClang::ParseRustVariantPart(
layout_info.field_offsets.insert({inner_field, 0});
}
+
+void DWARFASTParserClang::UpdateParsingProgress(std::string message) {
+ if (!m_parsing_progress_up) {
+ SymbolFile *dwarf = m_ast.GetSymbolFile();
+ if (!dwarf)
+ return;
+
+ auto *obj = dwarf->GetObjectFile();
+ if (!obj)
+ return;
+
+ m_parsing_progress_up = std::make_unique<Progress>(
+ "Parsing DWARF in " + obj->GetFileSpec().GetFilename().GetString());
+ }
+
+ m_parsing_progress_up->Increment(1, std::move(message));
+}
diff --git a/lldb/source/Plugins/SymbolFile/DWARF/DWARFASTParserClang.h b/lldb/source/Plugins/SymbolFile/DWARF/DWARFASTParserClang.h
index 8d4af203bb287..aed7c07d3f607 100644
--- a/lldb/source/Plugins/SymbolFile/DWARF/DWARFASTParserClang.h
+++ b/lldb/source/Plugins/SymbolFile/DWARF/DWARFASTParserClang.h
@@ -24,6 +24,7 @@
#include "Plugins/ExpressionParser/Clang/ClangASTImporter.h"
#include "Plugins/TypeSystem/Clang/TypeSystemClang.h"
+#include "lldb/Core/Progress.h"
#include <optional>
#include <vector>
@@ -135,6 +136,7 @@ class DWARFASTParserClang : public lldb_private::plugin::dwarf::DWARFASTParser {
DeclContextToDIEMap m_decl_ctx_to_die;
DIEToModuleMap m_die_to_module;
std::unique_ptr<lldb_private::ClangASTImporter> m_clang_ast_importer_up;
+ std::unique_ptr<lldb_private::Progress> m_parsing_progress_up;
/// @}
clang::DeclContext *
@@ -414,6 +416,8 @@ class DWARFASTParserClang : public lldb_private::plugin::dwarf::DWARFASTParser {
lldb_private::CompilerType &class_clang_type,
const lldb::AccessType default_accesibility,
lldb_private::ClangASTImporter::LayoutInfo &layout_info);
+
+ void UpdateParsingProgress(std::string message);
};
/// Parsed form of all attributes that are relevant for type reconstruction.
diff --git a/lldb/source/Plugins/SymbolFile/DWARF/SymbolFileDWARFDebugMap.cpp b/lldb/source/Plugins/SymbolFile/DWARF/SymbolFileDWARFDebugMap.cpp
index f066f13d51c5d..b20f2f6df210d 100644
--- a/lldb/source/Plugins/SymbolFile/DWARF/SymbolFileDWARFDebugMap.cpp
+++ b/lldb/source/Plugins/SymbolFile/DWARF/SymbolFileDWARFDebugMap.cpp
@@ -14,6 +14,7 @@
#include "lldb/Core/Module.h"
#include "lldb/Core/ModuleList.h"
#include "lldb/Core/PluginManager.h"
+#include "lldb/Core/Progress.h"
#include "lldb/Core/Section.h"
#include "lldb/Host/FileSystem.h"
#include "lldb/Utility/RangeMap.h"
@@ -1240,7 +1241,13 @@ TypeSP SymbolFileDWARFDebugMap::FindCompleteObjCDefinitionTypeForDIE(
void SymbolFileDWARFDebugMap::FindTypes(const TypeQuery &query,
TypeResults &results) {
std::lock_guard<std::recursive_mutex> guard(GetModuleMutex());
+ Progress progress(
+ llvm::formatv("Searching for type '{0}'",
+ query.GetTypeBasename().AsCString("<<UNKNOWN>>")));
ForEachSymbolFile([&](SymbolFileDWARF *oso_dwarf) {
+ if (auto *obj = oso_dwarf->GetObjectFile())
+ progress.Increment(1, obj->GetFileSpec().GetPath());
+
oso_dwarf->FindTypes(query, results);
return results.Done(query) ? IterationAction::Stop
: IterationAction::Continue;
|
|
Example of what the DIE parsing progress looks like: Screen.Recording.2024-05-08.at.10.44.13.movThe fact that the last progress event isn't cleared from the console is a problem. We'd have to decide at what point we want to destroy the |
| @@ -1240,7 +1241,13 @@ TypeSP SymbolFileDWARFDebugMap::FindCompleteObjCDefinitionTypeForDIE( | |||
| void SymbolFileDWARFDebugMap::FindTypes(const TypeQuery &query, | |||
| TypeResults &results) { | |||
| std::lock_guard<std::recursive_mutex> guard(GetModuleMutex()); | |||
| Progress progress( | |||
| llvm::formatv("Searching for type '{0}'", | |||
| query.GetTypeBasename().AsCString("<<UNKNOWN>>"))); | |||
| ForEachSymbolFile([&](SymbolFileDWARF *oso_dwarf) { | ||
| if (auto *obj = oso_dwarf->GetObjectFile()) | ||
| progress.Increment(1, obj->GetFileSpec().GetPath()); |
There was a problem hiding this comment.
What does this get rendered to?
It would be nice if it were:
Searching type "Foo" in "main.o"
but it almost looks like this would become
Searching for type "main.o"
?
There was a problem hiding this comment.
It would probably get rendered as Searching for type 'Foo': main.o if that filename is used as the details for Increment.
| auto from_name = from_name_parts.back(); | ||
|
|
||
| llvm::SmallVector<llvm::StringRef> to_name_parts; | ||
| llvm::SplitString(to_ast->getDisplayName(), to_name_parts, "/"); |
There was a problem hiding this comment.
What does an ast's DisplayName look like?
There was a problem hiding this comment.
StringRef::rsplit is going to be more efficient for this.
There was a problem hiding this comment.
What does an ast's DisplayName look like?
It's one of three:
Expression ASTContext for '" + m_filename + "'(expression AST)scratch ASTContext(target-wide AST)- a module name
| @@ -1411,3 +1414,35 @@ clang::Decl * | |||
| ClangASTImporter::ASTImporterDelegate::GetOriginalDecl(clang::Decl *To) { | |||
| return m_main.GetDeclOrigin(To).decl; | |||
| } | |||
|
|
|||
| void ClangASTImporter::ASTImporterDelegate::UpdateImportProgress( | |||
There was a problem hiding this comment.
The assertions in this code are going to blow up only in development builds. In release builds, you'll fall through the first assertion, and return because you try to cast nullptr to a NamedDecl (which will give you nullptr) and the function will fail silently. The second assertion will fail if from_ast or to_ast is nullptr, but the function doesn't return early there. It will call getDisplayName on from_ast and to_ast, one of which will crash anyway. Maybe we should consider an early return here too? Or maybe the function should return an llvm::Error?
There was a problem hiding this comment.
These asserts should never ever actually occur unless something about TypeSystemClang gets redesigned, at which point the intention was that these would flag in development builds/tests. But definitely valid question. For the cases where a nullptr could occur I did try to be consistent with early returns. I usually try to express the preconditions of the function in terms of asserts, but in this case I don't have strong opinion, I think doing an early return would make sense here. I remember some time last year @DavidSpickett proposed an assert macro that would fire in debug builds but early-return in release. Can't find that atm, not sure if it ever landed.
There was a problem hiding this comment.
cast nullptr to a NamedDecl (which will give you nullptr)
Actually, dyn_cast will abort if it gets a null pointer (dyn_cast_or_null is the version that forwards nullness) -- which makes this assert unnecessary. However, I think this is a very good example of an assert -- checking for things that "should not happen" without introducing overhead in the production codepath.
There was a problem hiding this comment.
I am somewhat worried about this slowing down the actual operations it is reporting progress on. I didn't really measure this, but intuitively, I'd expect that a one of these operations (parsing/importing one type) would be pretty fast, and that the whole process takes so long simply because performing a very large number of these ops.
Can you get some numbers on this? E.g., the number of events (per second?) that this generates, the timings of expression evaluation with/without the patch, or something like that?
| @@ -1411,3 +1414,35 @@ clang::Decl * | |||
| ClangASTImporter::ASTImporterDelegate::GetOriginalDecl(clang::Decl *To) { | |||
| return m_main.GetDeclOrigin(To).decl; | |||
| } | |||
|
|
|||
| void ClangASTImporter::ASTImporterDelegate::UpdateImportProgress( | |||
There was a problem hiding this comment.
cast nullptr to a NamedDecl (which will give you nullptr)
Actually, dyn_cast will abort if it gets a null pointer (dyn_cast_or_null is the version that forwards nullness) -- which makes this assert unnecessary. However, I think this is a very good example of an assert -- checking for things that "should not happen" without introducing overhead in the production codepath.
My understanding was that the progress increment is designed to be really cheap (writing two pointers) and that it's up to presentation layer to decide a t what frequency to update the UI. @JDevlieghere — is that perception correct? |
Even if the actual publishing of the progress event was free, there's still appears to be quite a bit of code executed before we reach that point. For example, the "if sending progress" block in |
You're correct about the presentation layer, but creating the progress reports isn't free and more recently we've added some bookkeeping to coalesce them. In the grand scheme of things they should be relatively cheap, but like timers I wouldn't put them in hot loops. |
|
If this turns out to be necessary, one way to rate-limit them would be to have a nesting depth counter. Assuming that these imports happen recursively we could create only Progress objects for the top n layers. |
Is the code that emits the progress event recursive too? The reason I ask is because on the command line, nested progress events will get shadowed. The same is true for coalesced progress events. I'm not sure how VSCode/DAP clients deal with this, so maybe they're shown there? Anyway, if the code is recursive, we might need to do something like we did for Swift, with one top-level event and callback that updates the details. |
There was a problem hiding this comment.
How many notifications happen during an expression? We want to make sure this doesn't slow down expression evaluation by any appreciable amount. If we spam these notifications, without having any throttling in place (I have an open patch for this I haven't been getting back to: #75769) I fear this will cause things to slow down a bit. I know IDEs are more sensitive to being blasted with progress updates.
I've been living on this patch for the past two weeks, debugging Clang/LLDB and haven't noticed a slowdown in the expression evaluator, but I'll try to follow-up with some concrete numbers.
Yes it is recursive, and some of the progress events do shadow each other. I'll take a look at what Swift does, thanks for the pointer! |
|
I attached to clang and printed an expression. That resulted in 16801 calls to So across the various scenarios i tested the slowdown is somewhere between 10-90 ms on average (though in other cases it's within noise).
@labath Mostly that's true. Occasionally these operations can take longer if we end up searching for types/functions across multiple object files (especially with swiftlang#8222). We could certainly consider some sort of rate limiting here. Or maybe find a better place to report progress on?
@JDevlieghere @adrian-prantl are there plans to change the presentation layer to prevent this kind of shadowing in the future? Would be nice if all we needed to do was report progress, and not worry about other progress events in the debugger being in-flight |
No, on the terminal it works that way by design. Unless you switch to something that takes full control of your screen (like curses) there's no good way to display multiple progress events at the same time and not doing the shadowing (i.e. letting more recent progress events through) defeats the purpose of highlighting long running operations. |
@JDevlieghere I know we discussed this in the past and it made sense to me, but I'm right now failing to connect the dots. Why couldn't the same single-line interface be used to print nested events something like this? |
Shadowing happens with unrelated events. The problem is that you don't want to show something like this: Or let's say you're doing some work in parallel: For a single event, you can update it, as we do for importing the Swift modules. For your example, today you can show something like this: Compared to your approach, you lose out on the additional context that's not part of the title/category before the colon. On the other hand, that's how we aggregate events in the progress manager. If we want to support nested related events, I think that wouldn't be too hard. An event could have a parent event ID and LLDB could append events that belong to the currently displayed event. But we'd still shadow unrelated events. |
Thanks for doing this. What do these numbers include? Is it just the operation it self, or everything leading up to it as well. For example, is "expr var" just the timing of the "expr" command, or attach command as well. If the latter, then what's the baseline? |
|
Sorry for the delayed response, just got back from vacation.
The benchmarks include the attach command as well. E.g., |
|
@labath baseline for just attaching is approximately |
|
Now that we don't search for the definition DIE when initially parsing a DIE, we could probably move this progress report to |
Thanks. I think this resolves my concerns about this patch. If we do find a particularly expensive/hot place reporting progress events, we can always remove it.
SGTM |
Michael137
force-pushed
the
lldb/expr-progress-events
branch
from
4fc71f1 to
d9d0e0d
Compare
|
Decided to go with something much simpler. We now report progress only in |
|
This PR rate limits things. Might be worth trying this out here to see if it helps: |
| @@ -1758,6 +1759,11 @@ DWARFASTParserClang::ParseStructureLikeDIE(const SymbolContext &sc, | |||
| } | |||
|
|
|||
| if (attrs.is_forward_declaration) { | |||
| Progress progress(llvm::formatv( | |||
| "Parsing forward declaration {0}: {1}", | |||
There was a problem hiding this comment.
It should either be "Resolving forward declaration" or "Parsing type". Otherwise it sounds like we take a long time to load a forward declaration itself.
Will try this out, though I haven't found any major performance issues as a result of the progress events added here. Maybe for different workloads this could get more noticeable. Should be easy enough to adjust if it turns out this does cause problems. |
|
Only buildkite test failure was |
…om DWARF (llvm#91452) This is an attempt at displaying the work that's being done by LLDB when waiting on type-completion events, e.g., when running an expression. This patch adds a single new progress event for cases where we search for the definition DIE of a forward declaration, which can be an expensive operation in the presence of many object files. (cherry picked from commit d32afb3)
This is an attempt at displaying the work that's being done by LLDB when waiting on type-completion events, e.g., when running an expression. We add three new progress reports (across three commits):
Some remaining questions:
Progressobjects? Since the progress completed event is only sent on object destruction