[lldb-dev] Evaluating the same expression at the same breakpoint gets slower after a certain number of steps
Gábor Márton via lldb-dev
lldb-dev at lists.llvm.org
Fri Jul 12 03:08:31 PDT 2019
Guilherme,
Could you please check if you have any structural differences between the
ASTs you see when
1) you first evaluate your expression at breakpoint A
2) you evaluate your expression the second time at breakpoint A ?
The AST of the expression evaluator's context is dumped once a TagDecl is
completed, but you need to enable a specific logging: (log enable lldb ast).
I have a theory about the root cause of the slowness you experience, but it
requires proof from your test scenario.
There are known problems with the lookup we use in LLDB [1].
If the lookup mechanism cannot find a symbol then clang::ASTImporter will
create a new AST node.
Thus I am expecting a growing AST in your case at 2) with duplicated and
redundant AST nodes.
Why would the grown AST results in any slowness?
Because the lookup we use is in `clang::DeclContext::localUncachedLookup()`
and it has a fallback branch which I assume is executed in your case:
```
// Slow case: grovel through the declarations in our chain looking for
// matches.
// FIXME: If we have lazy external declarations, this will not find them!
// FIXME: Should we CollectAllContexts and walk them all here?
for (Decl *D = FirstDecl; D; D = D->getNextDeclInContext()) {
if (auto *ND = dyn_cast<NamedDecl>(D))
if (ND->getDeclName() == Name)
Results.push_back(ND);
}
```
This for loop does a linear search on the list of the decls of a decl
context, which explains the slowing factor as the AST grows.
I wounder if you could help proving this theorem by first checking if the
AST grows and if yes then checking if this linear search is executed or not.
[1] If a symbol is in an `extern "C"` block then the existing lookup fails
to find it. I try to fix it in https://reviews.llvm.org/D61333
Thanks,
Gabor
On Thu, Jul 11, 2019 at 8:24 PM Jim Ingham via lldb-dev <
lldb-dev at lists.llvm.org> wrote:
> lldb realizes types from DWARF lazily. So for instance, if an expression
> refers to a pointer to type Foo, we won't necessarily realize the full type
> of Foo from DWARF to parse that expression. Then if you write a second
> expression that accesses a member of an object of type Foo, we will realize
> the full type for Foo. Then if you run the first expression again, the
> pointer to Foo type in the lldb type system will now point to a realized
> type of Foo. That should not make any difference, since if we were right
> the first time that we didn't need to know anything about Foo, it shouldn't
> matter whether the full type is realized or not.
>
> Similarly, the "expression with no side effects" could have also caused
> lldb to realize any number of other types. We find names from type
> information in two ways: looking in the realized types, and looking in the
> name indexes we read from DWARF or (on systems without accelerator tables)
> from indexing the DWARF manually. So the expression with no side effects
> will change the types in the realized types pool. That also "should not
> matter" because if the expression X was looking up by name, the lookup
> through the name indexes when the type wasn't realized yet should be
> equivalent to the lookup in the realized types.
>
> We really have no choice but to realize types lazily in this way, the
> debugger would just run way too slowly on big projects if we didn't. So
> the fact that one expression can change the state of the type system for a
> subsequent expression is a fact of life for lldb. But if the lookup
> mechanism is working properly, then these changes shouldn't matter. OTOH
> shouldn't and don't are not quite the same...
>
> Jim
>
>
> > On Jul 11, 2019, at 9:53 AM, Guilherme Andrade <guiandrade at google.com>
> wrote:
> >
> > Speaking more generally, can evaluating an expression with no side
> effects affect the outcome of subsequent evaluations? I.e, is it possible
> for the expression evaluation X to produce different results in the
> following scenarios?
> >
> > Scenario 1: <set of instructions A> <expression evaluation with no side
> effects> <set of instructions B> <expression evaluation X>
> > Scenario 2: <set of instructions A> <set of instructions B> <expression
> evaluation X>
> >
> > Thanks!
> >
> > On Tue, Jul 9, 2019 at 2:52 PM Guilherme Andrade <guiandrade at google.com>
> wrote:
> > Thanks for looking into this, Jason. I ended up realizing that it isn't
> about the number of evaluations; it is the exact location of the
> breakpoints that matters.
> >
> > I'm being able to consistently reproduce this by having two breakpoints
> (A and B) inside the same function, but B being inside the scope of a for
> loop that defines a couple extra variables. The first evaluation of
> 'undefinedVariable' at breakpoint A generates the following
> FindExternalLexicalDecls calls:
> >
> > FindExternalLexicalDecls[5] on (ASTContext*)000001566104F030 in 'Type0'
> (CXXRecordDecl*)0000015668964438
> > FindExternalLexicalDecls[6] on (ASTContext*)000001566104F030 in 'Type6'
> (CXXRecordDecl*)0000015668961BA8
> > FindExternalLexicalDecls[7] on (ASTContext*)000001566104F030 in 'Type7'
> (CXXRecordDecl*)0000015668961A68
> > FindExternalLexicalDecls[8] on (ASTContext*)000001566104F030 in 'Type8'
> (CXXRecordDecl*)0000015674F56208
> > FindExternalLexicalDecls[9] on (ASTContext*)000001566104F030 in 'Type9'
> (ClassTemplateSpecializationDecl*)0000015674F56CD0
> > FindExternalLexicalDecls[10] on (ASTContext*)000001566104F030 in
> 'Type10' (CXXRecordDecl*)0000015668964300
> > FindExternalLexicalDecls[11] on (ASTContext*)000001566104F030 in
> 'Type10' (CXXRecordDecl*)0000015668964300
> > FindExternalLexicalDecls[12] on (ASTContext*)000001566104F030 in 'Type0'
> (CXXRecordDecl*)0000015668964438
> > FindExternalLexicalDecls[13] on (ASTContext*)000001566104F030 in
> 'Type11' (EnumDecl*)0000015674F62778
> >
> > Then, the evaluation at breakpoint B generates:
> >
> > FindExternalLexicalDecls[19] on (ASTContext*)000001F1F6275320 in 'Type0'
> (CXXRecordDecl*)000001F1EA798868
> > FindExternalLexicalDecls[20] on (ASTContext*)000001F1F6275320 in 'Type1'
> (CXXRecordDecl*)000001F1EA799098
> > FindExternalLexicalDecls[21] on (ASTContext*)000001F1F6275320 in 'Type2'
> (ClassTemplateSpecializationDecl*)000001F1EA7A0D50
> > FindExternalLexicalDecls[22] on (ASTContext*)000001F1F6275320 in 'Type3'
> (CXXRecordDecl*)000001F1EA79D818
> > FindExternalLexicalDecls[23] on (ASTContext*)000001F1F6275320 in 'Type4'
> (CXXRecordDecl*)000001F1EA79D548
> > FindExternalLexicalDecls[24] on (ASTContext*)000001F1F6275320 in 'Type5'
> (CXXRecordDecl*)000001F1EA7A2A08
> > FindExternalLexicalDecls[25] on (ASTContext*)000001F1F6275320 in 'Type6'
> (CXXRecordDecl*)000001F1EA7BB368
> > FindExternalLexicalDecls[26] on (ASTContext*)000001F1F6275320 in 'Type7'
> (CXXRecordDecl*)000001F1EA7BB228
> > FindExternalLexicalDecls[27] on (ASTContext*)000001F1F6275320 in 'Type8'
> (CXXRecordDecl*)000001F1F68B9088
> > FindExternalLexicalDecls[28] on (ASTContext*)000001F1F6275320 in 'Type9'
> (ClassTemplateSpecializationDecl*)000001F1F68B2AC0
> > FindExternalLexicalDecls[29] on (ASTContext*)000001F1F6275320 in
> 'Type10' (CXXRecordDecl*)000001F1EA798730
> > FindExternalLexicalDecls[30] on (ASTContext*)000001F1F6275320 in
> 'Type10' (CXXRecordDecl*)000001F1EA798730
> > FindExternalLexicalDecls[31] on (ASTContext*)000001F1F6275320 in 'Type0'
> (CXXRecordDecl*)000001F1EA798868
> > FindExternalLexicalDecls[32] on (ASTContext*)000001F1F6275320 in
> 'Type11' (EnumDecl*)000001F1F68CB3E0
> > FindExternalLexicalDecls[33] on (ASTContext*)000001F1F6275320 in
> 'Type12' (CXXRecordDecl*)000001F1E2351F48
> >
> > And the subsequent evaluations at breakpoint A, which are slower,
> produce:
> >
> > FindExternalLexicalDecls[91] on (ASTContext*)000001566104F030 in 'Type0'
> (CXXRecordDecl*)000001566895C3B8
> > FindExternalLexicalDecls[92] on (ASTContext*)000001566104F030 in 'Type1'
> (CXXRecordDecl*)000001566895CBE8
> > FindExternalLexicalDecls[93] on (ASTContext*)000001566104F030 in 'Type2'
> (ClassTemplateSpecializationDecl*)00000156689678D0
> > FindExternalLexicalDecls[94] on (ASTContext*)000001566104F030 in 'Type3'
> (CXXRecordDecl*)0000015668964398
> > FindExternalLexicalDecls[95] on (ASTContext*)000001566104F030 in 'Type4'
> (CXXRecordDecl*)00000156689640C8
> > FindExternalLexicalDecls[96] on (ASTContext*)000001566104F030 in 'Type5'
> (CXXRecordDecl*)0000015674F608B8
> > FindExternalLexicalDecls[97] on (ASTContext*)000001566104F030 in 'Type6'
> (CXXRecordDecl*)0000015674F731B8
> > FindExternalLexicalDecls[98] on (ASTContext*)000001566104F030 in 'Type7'
> (CXXRecordDecl*)0000015674F73078
> > FindExternalLexicalDecls[99] on (ASTContext*)000001566104F030 in 'Type8'
> (CXXRecordDecl*)0000015674F7B278
> > FindExternalLexicalDecls[100] on (ASTContext*)000001566104F030 in
> 'Type9' (ClassTemplateSpecializationDecl*)0000015674F78CF0
> > FindExternalLexicalDecls[101] on (ASTContext*)000001566104F030 in
> 'Type10' (CXXRecordDecl*)000001566895C280
> > FindExternalLexicalDecls[102] on (ASTContext*)000001566104F030 in
> 'Type10' (CXXRecordDecl*)000001566895C280
> > FindExternalLexicalDecls[103] on (ASTContext*)000001566104F030 in
> 'Type0' (CXXRecordDecl*)000001566895C3B8
> > FindExternalLexicalDecls[104] on (ASTContext*)000001566104F030 in
> 'Type11' (EnumDecl*)0000015674F81510
> >
> > The FindExternalVisibleDecls entries remain the same among all
> evaluations at breakpoint A.
> >
> > So, Jim, if symbols are getting added at B or types are being completed,
> then the extra FindExternalLexicalDecls calls for Type1-5 is intended
> behavior?
> >
> > On Mon, Jul 8, 2019 at 7:04 PM Jim Ingham <jingham at apple.com> wrote:
> > Are any sources for symbols getting added to the process as you go
> along, like new shared library loads? You are asking for a non-existent
> name, so every new source of debug info is a new place to look.
> >
> > It's also possible that we are completing some types during the course
> of the expression evaluation, and then the newly completed types become
> themselves new places to look for this non-existent name.
> >
> > You can see what is getting looked up by turning in the expression log
> (log enable lldb expr) then looking for the FindExternalVisibleDecls
> entries.
> >
> > Jim
> >
> >
> > > On Jul 8, 2019, at 3:33 PM, Jason Molenda via lldb-dev <
> lldb-dev at lists.llvm.org> wrote:
> > >
> > > Hm, that's interesting.
> > >
> > > I tried running a debug lldb on /bin/ls. then I attached from another
> lldb. I put a breakpoint on CommandObjectTargetModulesLookup::DoExecute
> and resumed execution. In the debuggee lldb, I did
> > >
> > > tar mod loo -a 0
> > >
> > >
> > > and auto-repeated return so the same command would be executed over
> and over.
> > >
> > > In the debugger lldb, I tried adding a command to the breakpoint,
> > >
> > > br comm add
> > > p does_not_exist
> > > DONE
> > >
> > > and continuing - after a couple dozen times, I didn't see a slowdown.
> I tried adding a breakpoint condition,
> > >
> > > br mod -c 'doesNotExist == 1' 1
> > >
> > > and continuing, and didn't see a slowdown after a few dozen
> repetitions.
> > >
> > > I'm on macOS using .o file DWARF debugging.
> > >
> > > I'm sure there's a bug here, but it may be more specific to the
> platform and type of debug info that you're using? It could be that lldb is
> too small of a project to repo this problem too.
> > >
> > >
> > >
> > >> On Jul 4, 2019, at 11:38 AM, Guilherme Andrade via lldb-dev <
> lldb-dev at lists.llvm.org> wrote:
> > >>
> > >> I have two breakpoint inside methods that are called every frame (C++
> project using Unreal), and every time one of them is reached, I evaluate
> one expression (I'm being able to reproduce this using an undefined name,
> say "undefinedVariable"). After a few iterations (usually tens), the time
> it takes for LLDB to say that name doesn't exist increases, despite being
> the same expression, at the same breakpoint and the call stack remaining
> unchanged.
> > >>
> > >> I've noticed that the number of lexical Decl queries and imports
> conducted by Clang reported in 'Local metrics' increase.
> > >>
> > >> They go from:
> > >> Number of visible Decl queries by name : 29
> > >> Number of lexical Decl queries : 9
> > >> Number of imports initiated by LLDB : 15
> > >> Number of imports conducted by Clang : 827
> > >> Number of Decls completed : 5
> > >> Number of records laid out : 2
> > >>
> > >> To:
> > >> Number of visible Decl queries by name : 29
> > >> Number of lexical Decl queries : 14
> > >> Number of imports initiated by LLDB : 15
> > >> Number of imports conducted by Clang : 1342
> > >> Number of Decls completed : 5
> > >> Number of records laid out : 2
> > >>
> > >> Also, the number of SymbolFileDWARF operations in the logs jumps from
> 366 to 406.
> > >>
> > >> So, I've got two questions. 1) Is it safe to say that those extra
> imports and Decl queries are responsible for the performance loss? 2) Why
> do they happen?
> > >>
> > >> Thanks!
> > >> _______________________________________________
> > >> lldb-dev mailing list
> > >> lldb-dev at lists.llvm.org
> > >> https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev
> > >
> > > _______________________________________________
> > > lldb-dev mailing list
> > > lldb-dev at lists.llvm.org
> > > https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev
> >
> >
> > --
> > Guilherme Andrade | Software Engineer | guiandrade at google.com | Google
> Waterloo, Canada
>
> _______________________________________________
> lldb-dev mailing list
> lldb-dev at lists.llvm.org
> https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.llvm.org/pipermail/lldb-dev/attachments/20190712/fcb1ac9b/attachment-0001.html>
More information about the lldb-dev
mailing list