<div dir="ltr">Hey Jim,<div><br></div><div>We just noticed that '<span style="color:rgb(0,0,0);font-size:13px">target.experimental.inject-local-vars' is true by default. If we disable that experimental the performance for expression evaluation is significantly better.</span></div><div><br></div><div><font color="#000000">From the flag description:</font></div><div>"If true, inject local variables explicitly into the
expression text. This will fix symbol resolution
when there are name collisions between ivars and
local variables. But it can make expressions run
much more slowly."</div><div><br></div><div>I put together a simple example:</div><div>class bar {<br> public:<br> int foo = 2;<br> int Run(int foo) {<br> return foo + 1;<br> }<br>};<br></div><div><br></div><div>Evaluating 'foo' when stopped in bar.Run() seems to work as expected. Is there something I'm not capturing in my example? Do you have an example of a name collision that the experimental flag fixes?</div><div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Mon, Jul 15, 2019 at 1:53 PM Guilherme Andrade via lldb-dev <<a href="mailto:lldb-dev@lists.llvm.org">lldb-dev@lists.llvm.org</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div dir="ltr"><div class="gmail_default" style="font-size:small">Gábor,<br>Thanks for pointing this out to me. The AST changes - the resulting log increases from 7k lines to 11k. I also verified that the fallback branch is executed. 18k iterations during the first evaluation and 93k afterwards. However, that only results in a couple extra milliseconds slowness (~ 4 ms), whereas the overall performance hit is in the order of hundreds.<br><br>Jim,<br>Thank you for the explanation. I think I understand the lazy approach for types realization, but it is still not clear to me how that could cause the performance to degrade. If we encounter an already realized type, won't that save us work and make things run faster? Do you know of other points in the code that could be particularly sensitive to the realized types pool size (something like the branch Gábor mentioned)?<br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, Jul 12, 2019 at 6:08 AM Gábor Márton <<a href="mailto:martongabesz@gmail.com" target="_blank">martongabesz@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Guilherme,<br><br>Could you please check if you have any structural differences between the ASTs you see when<br>1) you first evaluate your expression at breakpoint A<br>2) you evaluate your expression the second time at breakpoint A ?<br>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).<div><br></div><div>I have a theory about the root cause of the slowness you experience, but it requires proof from your test scenario.</div><div>There are known problems with the lookup we use in LLDB [1].</div><div>If the lookup mechanism cannot find a symbol then clang::ASTImporter will create a new AST node.</div><div>Thus I am expecting a growing AST in your case at 2) with duplicated and redundant AST nodes.</div><div>Why would the grown AST results in any slowness?</div><div>Because the lookup we use is in `clang::DeclContext::localUncachedLookup()` and it has a fallback branch which I assume is executed in your case:</div><div>```</div><div> // Slow case: grovel through the declarations in our chain looking for<br> // matches.<br> // FIXME: If we have lazy external declarations, this will not find them!<br> // FIXME: Should we CollectAllContexts and walk them all here?<br> for (Decl *D = FirstDecl; D; D = D->getNextDeclInContext()) {<br> if (auto *ND = dyn_cast<NamedDecl>(D))<br> if (ND->getDeclName() == Name)<br> Results.push_back(ND);<br> }<br></div><div>```</div><div>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.</div><div>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.</div><div><br></div><div>[1] If a symbol is in an `extern "C"` block then the existing lookup fails to find it. I try to fix it in <a href="https://reviews.llvm.org/D61333" target="_blank">https://reviews.llvm.org/D61333</a><br></div><div><div><br></div><div>Thanks,</div><div>Gabor</div><div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, Jul 11, 2019 at 8:24 PM Jim Ingham via lldb-dev <<a href="mailto:lldb-dev@lists.llvm.org" target="_blank">lldb-dev@lists.llvm.org</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">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. <br>
<br>
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.<br>
<br>
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...<br>
<br>
Jim<br>
<br>
<br>
> On Jul 11, 2019, at 9:53 AM, Guilherme Andrade <<a href="mailto:guiandrade@google.com" target="_blank">guiandrade@google.com</a>> wrote:<br>
> <br>
> 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?<br>
> <br>
> Scenario 1: <set of instructions A> <expression evaluation with no side effects> <set of instructions B> <expression evaluation X><br>
> Scenario 2: <set of instructions A> <set of instructions B> <expression evaluation X><br>
> <br>
> Thanks!<br>
> <br>
> On Tue, Jul 9, 2019 at 2:52 PM Guilherme Andrade <<a href="mailto:guiandrade@google.com" target="_blank">guiandrade@google.com</a>> wrote:<br>
> 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.<br>
> <br>
> 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:<br>
> <br>
> FindExternalLexicalDecls[5] on (ASTContext*)000001566104F030 in 'Type0' (CXXRecordDecl*)0000015668964438<br>
> FindExternalLexicalDecls[6] on (ASTContext*)000001566104F030 in 'Type6' (CXXRecordDecl*)0000015668961BA8<br>
> FindExternalLexicalDecls[7] on (ASTContext*)000001566104F030 in 'Type7' (CXXRecordDecl*)0000015668961A68<br>
> FindExternalLexicalDecls[8] on (ASTContext*)000001566104F030 in 'Type8' (CXXRecordDecl*)0000015674F56208<br>
> FindExternalLexicalDecls[9] on (ASTContext*)000001566104F030 in 'Type9' (ClassTemplateSpecializationDecl*)0000015674F56CD0<br>
> FindExternalLexicalDecls[10] on (ASTContext*)000001566104F030 in 'Type10' (CXXRecordDecl*)0000015668964300<br>
> FindExternalLexicalDecls[11] on (ASTContext*)000001566104F030 in 'Type10' (CXXRecordDecl*)0000015668964300<br>
> FindExternalLexicalDecls[12] on (ASTContext*)000001566104F030 in 'Type0' (CXXRecordDecl*)0000015668964438<br>
> FindExternalLexicalDecls[13] on (ASTContext*)000001566104F030 in 'Type11' (EnumDecl*)0000015674F62778<br>
> <br>
> Then, the evaluation at breakpoint B generates:<br>
> <br>
> FindExternalLexicalDecls[19] on (ASTContext*)000001F1F6275320 in 'Type0' (CXXRecordDecl*)000001F1EA798868<br>
> FindExternalLexicalDecls[20] on (ASTContext*)000001F1F6275320 in 'Type1' (CXXRecordDecl*)000001F1EA799098<br>
> FindExternalLexicalDecls[21] on (ASTContext*)000001F1F6275320 in 'Type2' (ClassTemplateSpecializationDecl*)000001F1EA7A0D50<br>
> FindExternalLexicalDecls[22] on (ASTContext*)000001F1F6275320 in 'Type3' (CXXRecordDecl*)000001F1EA79D818<br>
> FindExternalLexicalDecls[23] on (ASTContext*)000001F1F6275320 in 'Type4' (CXXRecordDecl*)000001F1EA79D548<br>
> FindExternalLexicalDecls[24] on (ASTContext*)000001F1F6275320 in 'Type5' (CXXRecordDecl*)000001F1EA7A2A08<br>
> FindExternalLexicalDecls[25] on (ASTContext*)000001F1F6275320 in 'Type6' (CXXRecordDecl*)000001F1EA7BB368<br>
> FindExternalLexicalDecls[26] on (ASTContext*)000001F1F6275320 in 'Type7' (CXXRecordDecl*)000001F1EA7BB228<br>
> FindExternalLexicalDecls[27] on (ASTContext*)000001F1F6275320 in 'Type8' (CXXRecordDecl*)000001F1F68B9088<br>
> FindExternalLexicalDecls[28] on (ASTContext*)000001F1F6275320 in 'Type9' (ClassTemplateSpecializationDecl*)000001F1F68B2AC0<br>
> FindExternalLexicalDecls[29] on (ASTContext*)000001F1F6275320 in 'Type10' (CXXRecordDecl*)000001F1EA798730<br>
> FindExternalLexicalDecls[30] on (ASTContext*)000001F1F6275320 in 'Type10' (CXXRecordDecl*)000001F1EA798730<br>
> FindExternalLexicalDecls[31] on (ASTContext*)000001F1F6275320 in 'Type0' (CXXRecordDecl*)000001F1EA798868<br>
> FindExternalLexicalDecls[32] on (ASTContext*)000001F1F6275320 in 'Type11' (EnumDecl*)000001F1F68CB3E0<br>
> FindExternalLexicalDecls[33] on (ASTContext*)000001F1F6275320 in 'Type12' (CXXRecordDecl*)000001F1E2351F48<br>
> <br>
> And the subsequent evaluations at breakpoint A, which are slower, produce:<br>
> <br>
> FindExternalLexicalDecls[91] on (ASTContext*)000001566104F030 in 'Type0' (CXXRecordDecl*)000001566895C3B8<br>
> FindExternalLexicalDecls[92] on (ASTContext*)000001566104F030 in 'Type1' (CXXRecordDecl*)000001566895CBE8<br>
> FindExternalLexicalDecls[93] on (ASTContext*)000001566104F030 in 'Type2' (ClassTemplateSpecializationDecl*)00000156689678D0<br>
> FindExternalLexicalDecls[94] on (ASTContext*)000001566104F030 in 'Type3' (CXXRecordDecl*)0000015668964398<br>
> FindExternalLexicalDecls[95] on (ASTContext*)000001566104F030 in 'Type4' (CXXRecordDecl*)00000156689640C8<br>
> FindExternalLexicalDecls[96] on (ASTContext*)000001566104F030 in 'Type5' (CXXRecordDecl*)0000015674F608B8<br>
> FindExternalLexicalDecls[97] on (ASTContext*)000001566104F030 in 'Type6' (CXXRecordDecl*)0000015674F731B8<br>
> FindExternalLexicalDecls[98] on (ASTContext*)000001566104F030 in 'Type7' (CXXRecordDecl*)0000015674F73078<br>
> FindExternalLexicalDecls[99] on (ASTContext*)000001566104F030 in 'Type8' (CXXRecordDecl*)0000015674F7B278<br>
> FindExternalLexicalDecls[100] on (ASTContext*)000001566104F030 in 'Type9' (ClassTemplateSpecializationDecl*)0000015674F78CF0<br>
> FindExternalLexicalDecls[101] on (ASTContext*)000001566104F030 in 'Type10' (CXXRecordDecl*)000001566895C280<br>
> FindExternalLexicalDecls[102] on (ASTContext*)000001566104F030 in 'Type10' (CXXRecordDecl*)000001566895C280<br>
> FindExternalLexicalDecls[103] on (ASTContext*)000001566104F030 in 'Type0' (CXXRecordDecl*)000001566895C3B8<br>
> FindExternalLexicalDecls[104] on (ASTContext*)000001566104F030 in 'Type11' (EnumDecl*)0000015674F81510<br>
> <br>
> The FindExternalVisibleDecls entries remain the same among all evaluations at breakpoint A.<br>
> <br>
> 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?<br>
> <br>
> On Mon, Jul 8, 2019 at 7:04 PM Jim Ingham <<a href="mailto:jingham@apple.com" target="_blank">jingham@apple.com</a>> wrote:<br>
> 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.<br>
> <br>
> 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.<br>
> <br>
> You can see what is getting looked up by turning in the expression log (log enable lldb expr) then looking for the FindExternalVisibleDecls entries.<br>
> <br>
> Jim<br>
> <br>
> <br>
> > On Jul 8, 2019, at 3:33 PM, Jason Molenda via lldb-dev <<a href="mailto:lldb-dev@lists.llvm.org" target="_blank">lldb-dev@lists.llvm.org</a>> wrote:<br>
> > <br>
> > Hm, that's interesting.<br>
> > <br>
> > 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<br>
> > <br>
> > tar mod loo -a 0<br>
> > <br>
> > <br>
> > and auto-repeated return so the same command would be executed over and over.<br>
> > <br>
> > In the debugger lldb, I tried adding a command to the breakpoint,<br>
> > <br>
> > br comm add <br>
> > p does_not_exist<br>
> > DONE<br>
> > <br>
> > and continuing - after a couple dozen times, I didn't see a slowdown. I tried adding a breakpoint condition,<br>
> > <br>
> > br mod -c 'doesNotExist == 1' 1<br>
> > <br>
> > and continuing, and didn't see a slowdown after a few dozen repetitions.<br>
> > <br>
> > I'm on macOS using .o file DWARF debugging.<br>
> > <br>
> > 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.<br>
> > <br>
> > <br>
> > <br>
> >> On Jul 4, 2019, at 11:38 AM, Guilherme Andrade via lldb-dev <<a href="mailto:lldb-dev@lists.llvm.org" target="_blank">lldb-dev@lists.llvm.org</a>> wrote:<br>
> >> <br>
> >> 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.<br>
> >> <br>
> >> I've noticed that the number of lexical Decl queries and imports conducted by Clang reported in 'Local metrics' increase.<br>
> >> <br>
> >> They go from:<br>
> >> Number of visible Decl queries by name : 29<br>
> >> Number of lexical Decl queries : 9<br>
> >> Number of imports initiated by LLDB : 15<br>
> >> Number of imports conducted by Clang : 827<br>
> >> Number of Decls completed : 5<br>
> >> Number of records laid out : 2 <br>
> >> <br>
> >> To:<br>
> >> Number of visible Decl queries by name : 29<br>
> >> Number of lexical Decl queries : 14<br>
> >> Number of imports initiated by LLDB : 15<br>
> >> Number of imports conducted by Clang : 1342<br>
> >> Number of Decls completed : 5<br>
> >> Number of records laid out : 2<br>
> >> <br>
> >> Also, the number of SymbolFileDWARF operations in the logs jumps from 366 to 406.<br>
> >> <br>
> >> 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?<br>
> >> <br>
> >> Thanks!<br>
> >> _______________________________________________<br>
> >> lldb-dev mailing list<br>
> >> <a href="mailto:lldb-dev@lists.llvm.org" target="_blank">lldb-dev@lists.llvm.org</a><br>
> >> <a href="https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev" rel="noreferrer" target="_blank">https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev</a><br>
> > <br>
> > _______________________________________________<br>
> > lldb-dev mailing list<br>
> > <a href="mailto:lldb-dev@lists.llvm.org" target="_blank">lldb-dev@lists.llvm.org</a><br>
> > <a href="https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev" rel="noreferrer" target="_blank">https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev</a><br>
> <br>
> <br>
> -- <br>
> Guilherme Andrade | Software Engineer | <a href="mailto:guiandrade@google.com" target="_blank">guiandrade@google.com</a> | Google Waterloo, Canada<br>
<br>
_______________________________________________<br>
lldb-dev mailing list<br>
<a href="mailto:lldb-dev@lists.llvm.org" target="_blank">lldb-dev@lists.llvm.org</a><br>
<a href="https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev" rel="noreferrer" target="_blank">https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev</a></blockquote></div></div></div></div></blockquote></div></div>
_______________________________________________<br>
lldb-dev mailing list<br>
<a href="mailto:lldb-dev@lists.llvm.org" target="_blank">lldb-dev@lists.llvm.org</a><br>
<a href="https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev" rel="noreferrer" target="_blank">https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev</a><br>
</blockquote></div>