[lldb-dev] Dlopen extremely slow while LLDB is attached

[Scott Funkenhauser via lldb-dev]

Thanks Greg and Jason for pointing me in the right direction!

The results from my original tests were due to a timeout being triggered:

1524681484.092825651 (x86_64) /tmp/liblldb.so.7.0.0: Reading EH frame info
1524681489.783293724 error: timed out, status = timed out
1524681489.783379793 this = 0x00005555573DDC80, timeout = 5000000 us
1524681489.840902615 Breakpoint::ModulesChanged: num_modules: 1 load: 1
delete_locations: 0

I ran the exact same setup on a few other machines, and none of them hit
the timeout (so not sure what happened with my first test, more
investigation is required). Without the timeout, loading times of a
stripped shared library with LLDB attached was much more reasonable.

I then ran another test on a shared library that had DWARF sections. I
tracked down the majority of the extra time to be taking place inside
SymbolFileDWARF::Index(), which confirms your theory of the additoinal time
being due to indexing the DWARF sections.

I found this message (
http://lists.llvm.org/pipermail/llvm-dev/2018-January/120509.html) which
mentioned adding DWARF5 accelerator table support. Is it reasonable to
assume once that is implemented the time it takes to index DWARF sections
should be drastically reduced?

On Tue, Apr 24, 2018 at 4:36 PM Greg Clayton <clayborg at gmail.com> wrote:

>
>
> On Apr 24, 2018, at 12:26 PM, Scott Funkenhauser via lldb-dev <
> lldb-dev at lists.llvm.org> wrote:
>
> Hey guys,
>
> I'm trying to track down an issue I'm seeing where dlopen takes
> significantly longer to execute when LLDB is attached vs GDB (I've attached
> a simple program that I used to reproduce the issue).
> I was wondering if anybody had any idea what might be contributing to the
> additional execution time?
>
> Running without any debugger attached:
> $ ./lldb-load-sample
> Handle: 0x555555768c80
> Done loading. 848.27ms
> $ ./lldb-load-sample
> Handle: 0x555555768c80
> Done loading. 19.6047ms
>
> I noticed that the first run was significantly slower than any subsequent
> runs. Most likely due to some caching in Linux.
>
>
> For LLDB:
> (lldb) file lldb-load-sample
> Current executable set to 'lldb-load-sample' (x86_64).
> (lldb) run
> Process 82804 launched: '/lldb-load-sample' (x86_64)
> Handle: 0x555555768c80
> Done loading. 5742.78ms
> Process 82804 exited with status = 0 (0x00000000)
> (lldb) run
> Process 83454 launched: '/lldb-load-sample' (x86_64)
> Handle: 0x555555768c80
> Done loading. 19.4184ms
> Process 83454 exited with status = 0 (0x00000000)
>
> I noticed that subsequent runs were much faster (most likely due to some
> caching in Linux / LLDB), but that isn't relevant in my situation. Exiting
> LLDB and starting a new LLDB process still has an extremely long first run
> (In this case ~5.5s). There are other real world cases (initializing Vulkan
> which does a bunch of dlopens) where this can add 10s of seconds really
> slowing down iteration time.
>
>
> For GDB:
> (gdb) file lldb-load-sample
> Reading symbols from a.out...done.
> (gdb) run
> Starting program: /lldb-load-sample
> Handle: 0x555555768c80
> Done loading. 79.7276ms
> [Inferior 1 (process 85063) exited normally]
> (gdb) run
> Starting program: /lldb-load-sample
> Handle: 0x555555768c80
> Done loading. 80.325ms
> [Inferior 1 (process 85063) exited normally]
>
> As you can see the first run is slightly slower than running without a
> debugger attached, but it's not enough to be noticeable.
>
>
> I would venture to say LLDB is indexing the debug info during the shared
> library load breakpoint for some reason. GDB might not have any breakpoints
> or symbols to find to do in the shared library, so it might not end up
> parsing anything. So my guess is LLDB is looking for a symbol in any shared
> library that is loaded and when the shared library gets loaded it causes
> LLDB to do more work. All of LLDB's breakpoints are always looking for new
> locations to resolve (file and line breakpoints, breakpoints by name, and
> other plug-ins might be looking for things). You might try enabling with:
>
> (lldb) log enable --timestamp --file /tmp/log.txt dwarf info
> (lldb) file lldb-load-sample
> (lldb) run
> (lldb) quit
>
> then see if you can see any delays inside of LLDB.
>
> Greg
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.llvm.org/pipermail/lldb-dev/attachments/20180425/45611ddb/attachment.html>