<div dir="ltr">

<span style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">> This is a known issue, though I did not expect it to have that much of an</span><br style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial"><span style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">> impact. In fact, I have trouble reconciling this fact with your earlier</span><br style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial"><span style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">> statement that second and subsequent runs are much faster. The SO entry</span><br style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial"><span style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">> loading is something that has to happen on every run, so I don't see why</span><br style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial"><span style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">> the second run would be faster. This would be more consistent with the</span><br style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial"><span style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">> debug-info parsing case, as there we only index the dwarf once (if it</span><br style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial"><span style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">> hasn't changed). So, I think we are missing something here.</span><div><br></div><div>My statement that subsequent runs are much faster was for my simplified example (only running locally) that was meant to reproduce the problem I was seeing when initializing Vulkan. When I went back and tested initializing Vulkan (remotely) with 

<span style="color:rgb(34,34,34);font-family:sans-serif;font-size:13px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">SymbolFileDWARF::Index() commented out</span> it was still very slow, and I realized I was on the wrong path.</div><div><br></div><div>My latency to the server is normally only a few ms, which is why I initially ignored that difference between the two test environments. But it turns out a few ms is enough to make it twice as slow as running locally. This is what initially kicked off my investigation. I didn't catch this earlier because I was previously using GDB locally, and recently switched to using LLDB remotely. I hadn't compared LLDB local vs LLDB remote. My latest example to a server with a RTT of 18ms was to confirm that latency was the contributing factor. <br><br><div class="gmail_quote"><div dir="ltr">On Tue, May 1, 2018 at 6:44 AM Pavel Labath <<a href="mailto:labath@google.com">labath@google.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">On Mon, 30 Apr 2018 at 20:13, Scott Funkenhauser <<a href="mailto:sfunkenhauser@google.com" target="_blank">sfunkenhauser@google.com</a>><br>
wrote:<br>
<br>
> I messed up my test setup and incorrectly attributed the additional time.<br>
Parsing the DWARF sections does add additional time, but only increases by<br>
a small percentage.<br>
<br>
> By pure chance I noticed that the latency between the client and server<br>
had a huge impact. I did some tests against lldb_server running on a<br>
machine with a RTT of 18ms to the client. The difference in load time in my<br>
real world example (initializing Vulkan) was around 16x slower (~3.5s vs<br>
55s). I did some more digging and it looks like there are certain<br>
operations that perform a number of synchronous requests to the server<br>
(DYLDRendezvous::TakeSnapshot - updating SO entries and<br>
ThreadList::WillResume - grabbing SP and FP for every thread). Since all<br>
the requests are synchronous they are extremely sensitive to increased<br>
latency.<br>
<br>
> Is this a limitation of the gdb-server (can't handle parallel requests)?<br>
> Or is this not a common use case, and is not a known issue?<br>
<br>
This is a known issue, though I did not expect it to have that much of an<br>
impact. In fact, I have trouble reconciling this fact with your earlier<br>
statement that second and subsequent runs are much faster. The SO entry<br>
loading is something that has to happen on every run, so I don't see why<br>
the second run would be faster. This would be more consistent with the<br>
debug-info parsing case, as there we only index the dwarf once (if it<br>
hasn't changed). So, I think we are missing something here.<br>
<br>
In any case, this is not a fundamental limitation, and there are ways to<br>
remove that. The most obvious one is to move the rendezvous structure<br>
parsing to the server -- there is even a gdb packet for that, i don't know<br>
its name off-hand. Currently we have support for that in the client (for<br>
communicating with stubs that support it), but not in lldb-server.<br>
<br>
For the register reading part, we usually make sure we send the "important"<br>
registers in a batch, so that the client does not have to handle every one<br>
separately. At the moment it's only PC, because that used to be enough at<br>
some point. I don't know if anything changed in the client to make it ask<br>
for more info, but this is something that needs to be looked at more<br>
closely.<br>
<br>
> I enabled "gdb-remote all" logging, and searched for all all instances of<br>
'0x00005652ACF3F120' (the address of the connection object that is<br>
reporting the timeout?). Seems to be a pretty good corelation between the<br>
timeouts and 'Communication::SyncronizeWithReadThread', unfortunately I<br>
haven't had time to investigate further.<br>
<br>
> 1525110345.916504145 0x5652acefcbb0<br>
Broadcaster("lldb.process")::RestoreBroadcaster (about to pop<br>
listener("lldb.PlatformLinux.DebugProcess.hijack")=0x5652acf079a0)<br>
> 1525110345.916502953 this = 0x00005652ACF3F120, timeout = 5000000 us<br>
> --<br>
> 1525110345.919557333 0x7f0868000940<br>
'Communication::SyncronizeWithReadThread'<br>
Listener::FindNextEventInternal(broadcaster=(nil),<br>
broadcaster_names=(nil)[0], event_type_mask=0x00000000, remove=1) event<br>
0x7f086c0008c0<br>
> 525110345.919566154 this = 0x00005652ACF3F120, timeout = 5000000 us<br>
> --<br>
> 1525110346.123922110 0x7f0868000d10<br>
'Communication::SyncronizeWithReadThread'<br>
Listener::FindNextEventInternal(broadcaster=(nil),<br>
broadcaster_names=(nil)[0], event_type_mask=0x00000000, remove=1) event<br>
0x7f086c0008c0<br>
> 1525110346.123931408 this = 0x00005652ACF3F120, timeout = 5000000 us<br>
> --<br>
> 1525110346.152676821 0x7f0868006710<br>
'Communication::SyncronizeWithReadThread'<br>
Listener::FindNextEventInternal(broadcaster=(nil),<br>
broadcaster_names=(nil)[0], event_type_mask=0x00000000, remove=1) event<br>
0x7f086c0008c0<br>
> 1525110346.152685642 this = 0x00005652ACF3F120, timeout = 5000000 us<br>
> --<br>
> 1525110346.167683363 0x7f08682b2fe0<br>
'Communication::SyncronizeWithReadThread'<br>
Listener::FindNextEventInternal(broadcaster=(nil),<br>
broadcaster_names=(nil)[0], event_type_mask=0x00000000, remove=1) event<br>
0x7f086c0008c0<br>
> 1525110346.167692184 this = 0x00005652ACF3F120, timeout = 5000000 us<br>
I think the timeout quest is a red haring, tbh. These two are correlated,<br>
because they are both things that we need to do when the process stops<br>
(flush its STDIO after it stops, and start the read thread after we resume<br>
it). The run fast, and there are no timeouts involved.<br>
<br>
> --<br>
> 1525110351.172777176 error: timed out, status = timed out, uri =<br>
> 1525110351.172847271 this = 0x00005652ACF3F120, timeout = 5000000 us<br>
> 1525110356.173308611 error: timed out, status = timed out, uri =<br>
> 1525110356.173368216 this = 0x00005652ACF3F120, timeout = 5000000 us<br>
> 1525110361.175591230 error: timed out, status = timed out, uri =<br>
> 1525110361.175647497 this = 0x00005652ACF3F120, timeout = 5000000 us<br>
> 1525110366.180710316 error: timed out, status = timed out, uri =<br>
> 1525110366.180769205 this = 0x00005652ACF3F120, timeout = 5000000 us<br>
And I bet these happen while the process is running, so they do not impact<br>
the latency at all. It's just us waiting for the process to stop in a loop.<br>
</blockquote></div></div></div>