[lldb-dev] Evaluating the same expression at the same breakpoint gets slower after a certain number of steps
Jim Ingham via lldb-dev
lldb-dev at lists.llvm.org
Thu Jul 11 11:24:37 PDT 2019
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
More information about the lldb-dev
mailing list