[Bug gdb/17557] New: Very slow load due to millions of identical lseek syscalls opening shared libs

[Bug gdb/17557] New: Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

            Bug ID: 17557
           Summary: Very slow load due to millions of identical lseek
                    syscalls opening shared libs
           Product: gdb
           Version: HEAD
            Status: NEW
          Severity: normal
          Priority: P2
         Component: gdb
          Assignee: unassigned at sourceware dot org
          Reporter: tim@mr-dog.net

Hi,

When running my executable in gdb I have to wait around ten minutes (not an
exaggeration!) during which gdb's loading shared libraries.

Millions and millions of duplicate lseek calls are being made, with duplicate
offsets, into the same shared libraries.

The backtrace of the calls are always exactly the same too; it's this (from
stap):

 0x314c8f4bc0 : __lseek_nocancel+0x7/0x57 [/usr/lib64/libc-2.18.so]
 0x314c876596 : _IO_file_seekoff@@GLIBC_2.2.5+0x256/0x430
[/usr/lib64/libc-2.18.so]
 0x314c8750d7 : fseeko64+0x77/0xff [/usr/lib64/libc-2.18.so]
 0x769ac7 : bfd_seek+0x87/0x1d0 [/home/tjones/apps/gdb/bin/gdb]
 0x76fd21 : _bfd_generic_get_section_contents+0xa1/0xd0
[/home/tjones/apps/gdb/bin/gdb]
 0x78a4b3 : elf_x86_64_plt_sym_val+0xc3/0x100 [/home/tjones/apps/gdb/bin/gdb]
 0x7a47ac : _bfd_elf_get_synthetic_symtab+0x21c/0x380
[/home/tjones/apps/gdb/bin/gdb]
 0x78a0ea : elf_x86_64_get_synthetic_symtab+0x39a/0x460
[/home/tjones/apps/gdb/bin/gdb]
 0x534ccf : elf_symfile_read+0x1ef/0x900 [/home/tjones/apps/gdb/bin/gdb]
 0x5c8d4d : symbol_file_add_with_addrs+0x24d/0x660
[/home/tjones/apps/gdb/bin/gdb]
 0x70c6e9 : solib_read_symbols+0x129/0x1a0 [/home/tjones/apps/gdb/bin/gdb]
 0x70cba6 : solib_add.constprop.2+0x116/0x120 [/home/tjones/apps/gdb/bin/gdb]
 0x70d5f4 : handle_solib_event+0x44/0x50 [/home/tjones/apps/gdb/bin/gdb]
 0x573fa5 : bpstat_stop_status+0x605/0xe20 [/home/tjones/apps/gdb/bin/gdb]
 0x5e4dcf : handle_inferior_event.part.25+0x49f/0x2860
[/home/tjones/apps/gdb/bin/gdb]
 0x5e8c6e : fetch_inferior_event+0x15e/0x590 [/home/tjones/apps/gdb/bin/gdb]
 0x605783 : inferior_event_handler+0x83/0x330 [/home/tjones/apps/gdb/bin/gdb]
 0x603370 : process_event+0xa0/0xe0 [/home/tjones/apps/gdb/bin/gdb]
 0x6037ec : gdb_do_one_event+0x4c/0x2f0 [/home/tjones/apps/gdb/bin/gdb]
 0x603ad7 : start_event_loop+0x47/0x90 [/home/tjones/apps/gdb/bin/gdb]

I'm using git master code.

Here's some more system/gdb info:

GNU gdb (GDB) 7.8.50.20141105-cvs

Linux ### 3.16.7-200.fc20.x86_64 #1 SMP Thu Oct 30 18:12:41 UTC 2014 x86_64
x86_64 x86_64 GNU/Linux

Using built-in specs.
COLLECT_GCC=gcc
COLLECT_LTO_WRAPPER=/usr/libexec/gcc/x86_64-redhat-linux/4.8.3/lto-wrapper
Target: x86_64-redhat-linux
Configured with: ../configure --prefix=/usr --mandir=/usr/share/man
--infodir=/usr/share/info --with-bugurl=http://bugzilla.redhat.com/bugzilla
--enable-bootstrap --enable-shared --enable-threads=posix
--enable-checking=release --with-system-zlib --enable-__cxa_atexit
--disable-libunwind-exceptions --enable-gnu-unique-object
--enable-linker-build-id --with-linker-hash-style=gnu
--enable-languages=c,c++,objc,obj-c++,java,fortran,ada,go,lto --enable-plugin
--enable-initfini-array --enable-java-awt=gtk --disable-dssi
--with-java-home=/usr/lib/jvm/java-1.5.0-gcj-1.5.0.0/jre
--enable-libgcj-multifile --enable-java-maintainer-mode
--with-ecj-jar=/usr/share/java/eclipse-ecj.jar --disable-libjava-multilib
--with-isl=/builddir/build/BUILD/gcc-4.8.3-20140911/obj-x86_64-redhat-linux/isl-install
--with-cloog=/builddir/build/BUILD/gcc-4.8.3-20140911/obj-x86_64-redhat-linux/cloog-install
--with-tune=generic --with-arch_32=i686 --build=x86_64-redhat-linux
Thread model: posix
gcc version 4.8.3 20140911 (Red Hat 4.8.3-7) (GCC)

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

Tim Jones <tim@mr-dog.net> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |tim@mr-dog.net

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

--- Comment #1 from Tim Jones <tim@mr-dog.net> ---
Also:

This GDB was configured as "x86_64-unknown-linux-gnu".

... and build with:

./configure \
    --prefix=$HOME/apps/gdb \
    --with-build-config='bootstrap-O3' \
    --enable-lto \
    --enable-tui \
    --enable-gdbtk \
    --enable-gtk \
    --enable-plugins \
    --enable-install-libbfd \
    --with-mmap \
    --with-zlib \
    --enable-libmcheck \
    --with-babeltrace \
    --enable-gold=yes \
    --enable-threads \
    --disable-nls

Although, the same behaviour is seen with a minimal configure line as apposed
the above, so this make little difference.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

--- Comment #2 from Tim Jones <tim@mr-dog.net> ---
I've just build a debug gdb with:

./configure \
    --prefix=$HOME/apps/gdb.debug \
    --with-build-config='bootstrap-debug' \
    --with-lzma

Full backtrace at the same repeating point is:

#0  0x000000314c8f4bb0 in lseek64 () from /lib64/libc.so.6
#1  0x000000314c876596 in __GI__IO_file_seekoff () from /lib64/libc.so.6
#2  0x000000314c8750d7 in fseeko64 () from /lib64/libc.so.6
#3  0x000000000079ee93 in real_fseek (file=0x125ed30, offset=25633575,
whence=0) at bfdio.c:59
#4  0x000000000079fd4d in cache_bseek (abfd=0xfcdef0, offset=25633575,
whence=0) at cache.c:272
#5  0x000000000079f2a9 in bfd_seek (abfd=0xfcdef0, position=25633575,
direction=0) at bfdio.c:325
#6  0x00000000007a79ae in _bfd_generic_get_section_contents (abfd=0xfcdef0,
section=0x1277eb0, location=0x7fffffffbdc0, offset=55, count=4) at libbfd.c:882
#7  0x00000000007aa8b1 in bfd_get_section_contents (abfd=0xfcdef0,
section=0x1277eb0, location=0x7fffffffbdc0, offset=55, count=4) at
section.c:1578
#8  0x00000000007cad3a in elf_x86_64_plt_sym_val (i=21, plt=0x1277eb0,
rel=0x5d29910) at elf64-x86-64.c:5325
#9  0x00000000007e8024 in _bfd_elf_get_synthetic_symtab (abfd=0xfcdef0,
symcount=257408, syms=0x7ffff07a4010, dynsymcount=140294, dynsyms=0x5c17620,
ret=0x7fffffffc008) at elf.c:10077
#10 0x00000000007caf9d in elf_x86_64_get_synthetic_symtab (abfd=0xfcdef0,
symcount=257408, syms=0x7ffff07a4010, dynsymcount=140294, dynsyms=0x5c17620,
ret=0x7fffffffc008) at elf64-x86-64.c:5407
#11 0x0000000000542fcb in elf_read_minimal_symbols (objfile=0x1353900,
symfile_flags=8, ei=0x7fffffffc0a0) at elfread.c:1199
#12 0x000000000054311f in elf_symfile_read (objfile=0x1353900, symfile_flags=8)
at elfread.c:1266
#13 0x00000000005db85d in read_symbols (objfile=0x1353900, add_flags=8) at
symfile.c:875
#14 0x00000000005dbe58 in syms_from_objfile_1 (objfile=0x1353900,
addrs=0x135c1a0, add_flags=8) at symfile.c:1078
#15 0x00000000005dbe9b in syms_from_objfile (objfile=0x1353900,
addrs=0x135c1a0, add_flags=8) at symfile.c:1094
#16 0x00000000005dc093 in symbol_file_add_with_addrs (abfd=0xfcdef0,
name=0x103d200
"/build/branches/tim-jones/super-portion.release.impl/gnu/so/lib/libdedupe_ut.so",
add_flags=8, addrs=0x135c1a0, flags=2, parent=0x0) at symfile.c:1191
#17 0x00000000005dc288 in symbol_file_add_from_bfd (abfd=0xfcdef0,
name=0x103d200
"/build/branches/tim-jones/super-portion.release.impl/gnu/so/lib/libdedupe_ut.so",
add_flags=8, addrs=0x135c1a0, flags=2, parent=0x0) at symfile.c:1280
#18 0x00000000007418ed in solib_read_symbols (so=0x103cff0, flags=8) at
solib.c:636
#19 0x0000000000741fbf in solib_add (pattern=0x0, from_tty=0, target=0xd306c0
<current_target>, readsyms=1) at solib.c:954
#20 0x0000000000742715 in handle_solib_event () at solib.c:1270
#21 0x000000000057dcf0 in bpstat_stop_status (aspace=0xeab5e0,
bp_addr=211732674918, ptid=..., ws=0x7fffffffc6b0) at breakpoint.c:5543
#22 0x00000000005fc163 in handle_signal_stop (ecs=0x7fffffffc690) at
infrun.c:4375
#23 0x00000000005fb67b in handle_inferior_event (ecs=0x7fffffffc690) at
infrun.c:4052
#24 0x00000000005f9a0c in fetch_inferior_event (client_data=0x0) at
infrun.c:3203
#25 0x000000000061d02b in inferior_event_handler (event_type=INF_REG_EVENT,
client_data=0x0) at inf-loop.c:57
#26 0x00000000004bb392 in handle_target_event (error=0, client_data=0x0) at
linux-nat.c:4446
#27 0x000000000061adbf in handle_file_event (data=...) at event-loop.c:762
#28 0x000000000061a2a6 in process_event () at event-loop.c:339
#29 0x000000000061a348 in gdb_do_one_event () at event-loop.c:391
#30 0x000000000061a3bd in start_event_loop () at event-loop.c:428
#31 0x000000000061be26 in cli_command_loop (data=0x0) at event-top.c:181
#32 0x00000000006121ba in current_interp_command_loop () at interps.c:317
#33 0x0000000000613382 in captured_command_loop (data=0x0) at main.c:321
#34 0x000000000060f07f in catch_errors (func=0x613367 <captured_command_loop>,
func_args=0x0, errstring=0x901d2e "", mask=RETURN_MASK_ALL) at exceptions.c:237
#35 0x0000000000614880 in captured_main (data=0x7fffffffcb60) at main.c:1149
#36 0x000000000060f07f in catch_errors (func=0x61377f <captured_main>,
func_args=0x7fffffffcb60, errstring=0x901d2e "", mask=RETURN_MASK_ALL) at
exceptions.c:237
#37 0x00000000006148a9 in gdb_main (args=0x7fffffffcb60) at main.c:1157
#38 0x000000000045f7f4 in main (argc=11, argv=0x7fffffffcc68) at gdb.c:32
#39 0x000000314c821d65 in __libc_start_main () from /lib64/libc.so.6
#40 0x000000000045f6e9 in _start ()

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[xdje42 at gmail dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

Doug Evans <xdje42 at gmail dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |xdje42 at gmail dot com

--- Comment #3 from Doug Evans <xdje42 at gmail dot com> ---
Yeah, more than a little clumsy.

A lot of these are coming from bfd, I haven't looked into what's involved in
making bfd smarter.

However, it's not clear to me that the lseek calls are the high order bit of
the slowness I've seen in my benchmarks.  Although bfd may have changed since I
last collected data.

btw, another thing I'm seeing is massive amounts of calls to
rt_sigaction,rt_sigprocmask to handle SIGSEGV - presumably the new segv
handling we're wrapped around the demangler.  I still have to measure the cost
of doing it per-symbol.

We need to add a mega-program generator to our performance testsuite, and
provide a shareable framework from which to collect and share data.

btw, I'm assuming you're not using .gdb_index
(please correct me if I'm wrong).
https://sourceware.org/gdb/current/onlinedocs/gdb/Index-Files.html#Index-Files
It would be interesting to compare what you see with and without .gdb_index.
.gdb_index won't help with reading ELF symbols (which is where more of the
lseeks are coming from) but it would be interesting data to have.
The index can be added to any program (or, hopefully, .so) with the
gdb-add-index program that comes with gdb.
[Only do this if you have time and the inclination of course.]

Also, OOC, how many shared libraries?
e.g., what's the output of "ldd $program | wc" ?

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

--- Comment #4 from Tim Jones <tim@mr-dog.net> ---
Hi, the so's we've using (from ldd) are just the usual suspects, a few boost
so's, and we've three of our own. Those three of our own have a total of 465302
symbols between them, with a total size of just over half a gig (debug build)
(I can't specifically list the ldd output here).

I'll give gdb-add-index a go too ...

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

--- Comment #5 from Tim Jones <tim@mr-dog.net> ---
Blimey, gdb-add-index's slow with these so's. I'm essentially moving the time
to post compilation from gdb run, so not much help.

I'll still investigate the use of this though as a possible addition to debug
builds as a norm if it's seems beneficial - that's another story though.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

--- Comment #6 from Tim Jones <tim@mr-dog.net> ---
$ time gdb-add-index ...

real    6m38.219s
user    3m9.694s
sys     3m26.859s

That's just one of the three shared libs!

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

--- Comment #7 from Tim Jones <tim@mr-dog.net> ---
The resulting effect on gdb load times when using gdb-add-index, if any, is
negligible.

Are there any bfd alternatives?

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[gbenson at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

Gary Benson <gbenson at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |gbenson at redhat dot com

--- Comment #8 from Gary Benson <gbenson at redhat dot com> ---
You can easily check whether the demangler crash catcher is impacting
performance with "maint set catch-demangler-crashes off".  It made no
difference when I tried it, which is why I left the segfault handler
so narrowly applied.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

--- Comment #9 from Tim Jones <tim@mr-dog.net> ---
Hi Gary, I've just been trying that too, no difference here either.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[gbenson at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

--- Comment #10 from Gary Benson <gbenson at redhat dot com> ---
That's good to know, thanks Tim.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug gdb/17557] Very slow load due to millions of identical lseek syscalls opening shared libs

[tim@mr-dog.net]

https://sourceware.org/bugzilla/show_bug.cgi?id=17557

--- Comment #11 from Tim Jones <tim@mr-dog.net> ---
With recent gdb update, although I can't say for sure which specifically, the
load times have dramatically decreased, they even now seem quicker than I
remember before the slowdown began.

I've made no changes to build options/tools since, just updated gdb from
master.

-- 
You are receiving this mail because:
You are on the CC list for the bug.