[lldb-dev] Evaluating the same expression at the same breakpoint gets slower after a certain number of steps
Guilherme Andrade via lldb-dev
lldb-dev at lists.llvm.org
Tue Jul 9 11:52:12 PDT 2019
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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.llvm.org/pipermail/lldb-dev/attachments/20190709/7cccee97/attachment-0001.html>
More information about the lldb-dev
mailing list