Terminally slow (75 seconds) on some steps

Terminally slow (75 seconds) on some steps

[Robert Vazan]

I am trying to debug large program and I am observing unusual slowdown.
I don't have any breakpoints, I am just running the app. I measured 75
seconds of wall clock for single click operation that takes fraction of
second outside debugger. Process time (as viewed by ps) of gdb increased
by 68 seconds. I get realtime reaction with some operations and this
delay with some other operations. When single stepping, it seems that
the more lines must be executed the more time it takes in debugger (but
this is in 1-5 seconds range).

As if gdb was emulating every instruction. I know this isn't the case.
However, breakpoints cause interrupts, so maybe gdb is being bogged down
by some other interrupts, timer maybe? Given that single step can take
one or more seconds, few timers could quickly accumulate to minute.

I have also this problem that I cannot run the program twice per
session, so I have to restart gdb and consequently reload symbols. I
have aging snapshot from 1. April 2002.

Re: Terminally slow (75 seconds) on some steps

[Andrew Cagney]

> I am trying to debug large program and I am observing unusual slowdown.
> I don't have any breakpoints, I am just running the app. I measured 75
> seconds of wall clock for single click operation that takes fraction of
> second outside debugger. Process time (as viewed by ps) of gdb increased
> by 68 seconds. I get realtime reaction with some operations and this
> delay with some other operations. When single stepping, it seems that
> the more lines must be executed the more time it takes in debugger (but
> this is in 1-5 seconds range).
> 
> As if gdb was emulating every instruction. I know this isn't the case.
> However, breakpoints cause interrupts, so maybe gdb is being bogged down
> by some other interrupts, timer maybe? Given that single step can take
> one or more seconds, few timers could quickly accumulate to minute.
> 
> I have also this problem that I cannot run the program twice per
> session, so I have to restart gdb and consequently reload symbols. I
> have aging snapshot from 1. April 2002.

Is this a threaded program on GNU/Linux?  5.3 contained a major 
performance improvement for threaded debugging.

Also, something from April '02 is seriously old.  Try either 5.3, or a 
6.0 snap (see http://www.gnu.org/software/gdb/download/)

Re: Terminally slow (75 seconds) on some steps

[Robert Vazan]

On Thu, 17 Jul 2003 12:34:42 -0400 Andrew Cagney <ac131313@redhat.com> wrote:

> Is this a threaded program on GNU/Linux?  5.3 contained a major 
> performance improvement for threaded debugging.

Threads are only planned. There is a lot of locks, but only one thread.

> Also, something from April '02 is seriously old.  Try either 5.3, or a 
> 6.0 snap (see http://www.gnu.org/software/gdb/download/)

I have here Cvs HEAD and it gives 68->11 seconds improvement. It still
isn't the same as outside debugger, but it's usable, especially because
single-stepping is faster too.

Re: Terminally slow (75 seconds) on some steps

[Andrew Cagney]

> On Thu, 17 Jul 2003 12:34:42 -0400 Andrew Cagney <ac131313@redhat.com> wrote:
> 
> 
>> Is this a threaded program on GNU/Linux?  5.3 contained a major 
>> performance improvement for threaded debugging.
> 
> 
> Threads are only planned. There is a lot of locks, but only one thread.
> 
> 
>> Also, something from April '02 is seriously old.  Try either 5.3, or a 
>> 6.0 snap (see http://www.gnu.org/software/gdb/download/)
> 
> 
> I have here Cvs HEAD and it gives 68->11 seconds improvement. It still
> isn't the same as outside debugger, but it's usable, especially because
> single-stepping is faster too.

11 seconds per step?  Still painfully slow :-(

What exactly is the system your using?  Can you capture 
strace/ktrace/truss output for GDB doing a stepi?

By `locks' you mean?  If the program is using lots of signals then, 
again, its going to get slow - they have to go through GDB.

enjoy,
Andrew

Re: Terminally slow (75 seconds) on some steps

[Robert Vazan]

On Fri, 18 Jul 2003 17:56:27 -0400 Andrew Cagney <ac131313@redhat.com> wrote:

> 11 seconds per step?  Still painfully slow :-(

11 seconds for application startup. That's gdb's cpu time. Application
has 0 seconds of run time. Later some steps take 2 seconds, but some
steps are interactive. The unusual thing is that my application freezes
for those 2 seconds and then does the rest very quickly. That's without
any breakpoints, just running it in debugger.

> What exactly is the system your using?  Can you capture 
> strace/ktrace/truss output for GDB doing a stepi?

I have no clue what are above three tools, but stepi is interactive. At
least I didn't bother to find the point where those 2 seconds are spent.

> By `locks' you mean?

System native mutexes, I guess.

Re: Terminally slow (75 seconds) on some steps

[Andrew Cagney]

> On Fri, 18 Jul 2003 17:56:27 -0400 Andrew Cagney <ac131313@redhat.com> wrote:
> 
> 
>> 11 seconds per step?  Still painfully slow :-(
> 
> 
> 11 seconds for application startup. That's gdb's cpu time. Application
> has 0 seconds of run time. Later some steps take 2 seconds, but some
> steps are interactive. The unusual thing is that my application freezes
> for those 2 seconds and then does the rest very quickly. That's without
> any breakpoints, just running it in debugger.

So 11 seconds after you typed `run'.
(The word startup can either be appled to that time after "run", or the 
time for gdb to reach the first "(gdb)" prompt :-().

Lots of shared libraries?

Is it reproducable?

>> What exactly is the system your using?  Can you capture 
>> strace/ktrace/truss output for GDB doing a stepi?
> 
> 
> I have no clue what are above three tools, but stepi is interactive. At
> least I didn't bother to find the point where those 2 seconds are spent.

Which operating system?  That determines the tool you'll be using.

"step" is implemented using multiple "stepi".  A slowdown can either be 
two many "stepi"s or a slow "stepi" implementation.

>> By `locks' you mean?
> 
> 
> System native mutexes, I guess.

Which operating system?

Andrew

Re: Terminally slow (75 seconds) on some steps

[Robert Vazan]

On Mon, 21 Jul 2003 10:21:08 -0400 Andrew Cagney <ac131313@redhat.com> wrote:

> So 11 seconds after you typed `run'.
> (The word startup can either be appled to that time after "run", or the 
> time for gdb to reach the first "(gdb)" prompt :-().

Sorry, 11 seconds after "run" command. Gdb startup takes about one
second.

> Lots of shared libraries?

Mostly wxWindows, but there are other libraries:

        libwx_gtkd-2.4.so.0 => /usr/lib/libwx_gtkd-2.4.so.0 (0x40019000)
        libresolv.so.2 => /lib/libresolv.so.2 (0x4053a000)
        libcrypt.so.1 => /lib/libcrypt.so.1 (0x4054a000)
        libdl.so.2 => /lib/libdl.so.2 (0x40577000)
        libstdc++.so.5 => /usr/lib/libstdc++.so.5 (0x4057a000)
        libm.so.6 => /lib/libm.so.6 (0x40626000)
        libgcc_s.so.1 => /lib/libgcc_s.so.1 (0x40647000)
        libpthread.so.0 => /lib/libpthread.so.0 (0x4064f000)
        libc.so.6 => /lib/libc.so.6 (0x4069e000)
        libgtk-1.2.so.0 => /usr/lib/libgtk-1.2.so.0 (0x407ae000)
        libgdk-1.2.so.0 => /usr/lib/libgdk-1.2.so.0 (0x408d3000)
        libgmodule-1.2.so.0 => /usr/lib/libgmodule-1.2.so.0 (0x40907000)
        libgthread-1.2.so.0 => /usr/lib/libgthread-1.2.so.0 (0x4090a000)
        libglib-1.2.so.0 => /usr/lib/libglib-1.2.so.0 (0x4090e000)
        libXi.so.6 => /usr/X11R6/lib/libXi.so.6 (0x40931000)
        libXext.so.6 => /usr/X11R6/lib/libXext.so.6 (0x40939000)
        libX11.so.6 => /usr/X11R6/lib/libX11.so.6 (0x40946000)
        libpng.so.2 => /usr/lib/libpng.so.2 (0x40a20000)
        libjpeg.so.62 => /usr/lib/libjpeg.so.62 (0x40a4b000)
        libtiff.so.3 => /usr/lib/libtiff.so.3 (0x40a6b000)
        libz.so.1 => /usr/lib/libz.so.1 (0x40aad000)
        /lib/ld-linux.so.2 => /lib/ld-linux.so.2 (0x40000000)

> Is it reproducable?

Yes. If you want to try it, get Mahogany from anonymous Cvs.

cvs -d:pserver:anonymous@cvs.sourceforge.net:/cvsroot/mahogany login
cvs -d:pserver:anonymous@cvs.sourceforge.net:/cvsroot/mahogany checkout M
mkdir build; cd build
./M/configure --enable-debug --with-experimental --with-wxdebug
    --with-dmalloc
make && make install
src/M &

As I remember.

> >> What exactly is the system your using?  Can you capture 
> >> strace/ktrace/truss output for GDB doing a stepi?
> > 
> > 
> > I have no clue what are above three tools, but stepi is interactive. At
> > least I didn't bother to find the point where those 2 seconds are
> spent.
> 
> Which operating system?  That determines the tool you'll be using.

Sorry, Linux with 2.4 kernel.

> "step" is implemented using multiple "stepi".  A slowdown can either be 
> two many "stepi"s or a slow "stepi" implementation.

Gdb isn't doing any step/stepi in above tests. It's just big run without
breakpoints. Of course, I am doing steps when debugging, but with new
gdb, I haven't yet stumbled into single place where it is
non-interactive. I would have to do binary search over startup code, but
experience with old gdb tells that the cost is distributed.

> >> By `locks' you mean?
> > 
> > 
> > System native mutexes, I guess.
> 
> Which operating system?

Linux. wxWindows hides this carefully, but libpthread seems to be used.

Re: Terminally slow (75 seconds) on some steps

[Andrew Cagney]

> On Mon, 21 Jul 2003 10:21:08 -0400 Andrew Cagney <ac131313@redhat.com> wrote:
> 
> 
>> So 11 seconds after you typed `run'.
>> (The word startup can either be appled to that time after "run", or the 
>> time for gdb to reach the first "(gdb)" prompt :-().
> 
> 
> Sorry, 11 seconds after "run" command. Gdb startup takes about one
> second.

good (but the time is bad).

>> Lots of shared libraries?

Ok, during library load, GDB has to constantly start/stop the target - 
and that slows things down.  Would you be able to oprofile your entire 
system so its possible to see exactly where that 11 seconds goes?

A simple gprof isn't sufficient: it is the combination of GDB <-> 
libthread-db? <-> kernel <-> program, that slows things down.

The speed improvement in moving from 5.2 -> 5.2 came from identifying a 
situtation where GDB was performing millions of system calls.  There 
will likely be other cases.

I suspect, because of what you'r using, GDB is loading up libthread-db 
and that may also add to the load.

Andrew

Re: Terminally slow (75 seconds) on some steps

[Robert Vazan]

On Tue, 05 Aug 2003 01:20:26 -0400 Andrew Cagney <ac131313@redhat.com>
wrote:

> Ok, during library load, GDB has to constantly start/stop the target - 
> and that slows things down.  Would you be able to oprofile your entire 
> system so its possible to see exactly where that 11 seconds goes?

Where can I get this "oprofile"?

Re: Terminally slow (75 seconds) on some steps

[Andrew Cagney]

Try here:
http://oprofile.sourceforge.net/
your system may already include a pre-packaged version.

Andrew


> On Tue, 05 Aug 2003 01:20:26 -0400 Andrew Cagney <ac131313@redhat.com>
> wrote:
> 
> 
>> Ok, during library load, GDB has to constantly start/stop the target - 
>> and that slows things down.  Would you be able to oprofile your entire 
>> system so its possible to see exactly where that 11 seconds goes?
> 
> 
> Where can I get this "oprofile"?
> 
> 

Re: Terminally slow (75 seconds) on some steps

[Robert Vazan]

> > On Tue, 05 Aug 2003 01:20:26 -0400 Andrew Cagney <ac131313@redhat.com>
> > wrote:
> > 
> >> Ok, during library load, GDB has to constantly start/stop the target
> >> and that slows things down.  Would you be able to oprofile your
> entire 
> >> system so its possible to see exactly where that 11 seconds goes?

OK, I have here running oprofile. I am not sure what sort of report do you
need. I can copy-n-paste reports to list or publish larger files on my
website. Here go some simple statistics: run without gdb[1], run inside
gdb[2], symbol details from gdb run[3]. Oprofile cannot do call graphs, I
hope you get something out of these numbers.

[1]

     2371 30.3352 vmlinux
      736  9.4166 XFree86
      729  9.3270 ld-2.3.1.so
      595  7.6126 libwx_based-2.5.so.0.0.0
      487  6.2308 libwx_gtkd_core-2.5.so.0.0.0
      471  6.0261 libc-2.3.1.so
      454  5.8086 M
...

[2]

    10567 37.2826 vmlinux
     8537 30.1203 gdb
     4402 15.5312 libc-2.3.1.so
      786  2.7732 ld-2.3.1.so
      622  2.1945 XFree86
      511  1.8029 libwx_based-2.5.so.0.0.0
      455  1.6053 M
...

[3]

00000000 4402     15.5317     libc-2.3.1.so            (no symbols)
080e40e0 1134      4.0011     gdb                      bcache
c01221cc 1011      3.5671     vmlinux                  file_read_actor
c01dc330 955       3.3696     vmlinux                  __generic_copy_to_user
c011f6b8 663       2.3393     vmlinux                  do_anonymous_page
00000000 622       2.1946     XFree86                  (no symbols)
08134b74 574       2.0253     gdb                      read_partial_die
c0118f2c 516       1.8206     vmlinux                  access_process_vm
080e3fc0 459       1.6195     gdb                      hash
00000000 384       1.3549     libglib-1.2.so.0.0.10    (no symbols)
c0105370 369       1.3020     vmlinux                  default_idle
081b7f7c 360       1.2702     gdb                      htab_find_slot_with_hash
08134fe4 307       1.0832     gdb                      read_attribute_value
081b8218 292       1.0303     gdb                      htab_hash_string
c0135408 292       1.0303     vmlinux                  link_path_walk
c0106d54 283       0.9985     vmlinux                  system_call
c0147650 273       0.9632     vmlinux                  proc_lookup
081351bc 246       0.8680     gdb                      read_attribute
00006e48 244       0.8609     ld-2.3.1.so              do_lookup
0813195c 240       0.8468     gdb                      add_partial_symbol
08135560 237       0.8362     gdb                      read_unsigned_leb128
c0126294 231       0.8150     vmlinux                  kmem_cache_free
00000000 226       0.7974     libX11.so.6.2            (no symbols)
00007042 215       0.7586     ld-2.3.1.so              do_lookup_versioned
c012da38 209       0.7374     vmlinux                  fput
c0126100 208       0.7339     vmlinux                  kmem_cache_alloc
081354e4 204       0.7198     gdb                      read_indirect_string
c0127834 200       0.7057     vmlinux                  rmqueue
0000dc18 188       0.6633     ld-2.3.1.so              strcmp
c01397f4 185       0.6527     vmlinux                  do_select
00002210 168       0.5928     unix.o                   unix_poll
c013e84c 164       0.5786     vmlinux                  clean_inode
00000000 160       0.5645     libgdk-1.2.so.0.9.1      (no symbols)
080a43f0 159       0.5610     gdb                      symbol_set_names
c0127640 155       0.5469     vmlinux                  __free_pages_ok
081568b4 147       0.5187     gdb                      bfd_getl32
080aa8b0 139       0.4904     gdb                      add_psymbol_to_list
c0135f24 138       0.4869     vmlinux                  open_namei
c010fbe4 134       0.4728     vmlinux                  schedule
00000000 131       0.4622     libgtk-1.2.so.0.9.1      (no symbols)
c013cc00 120       0.4234     vmlinux                  dput
c013d204 117       0.4128     vmlinux                  d_alloc
c013d3cc 110       0.3881     vmlinux                  d_lookup
08134b30 102       0.3599     gdb                      dwarf2_lookup_abbrev
081b08e8 101       0.3564     gdb                      demangle_prefix
08131800 97        0.3422     gdb                      scan_partial_symbols
c012db08 97        0.3422     vmlinux                  fget
080fbba0 96        0.3387     gdb                      xmmalloc
080fd028 93        0.3281     gdb                      strcmp_iw_ordered
c0146fd0 93        0.3281     vmlinux                  proc_pid_lookup
c013ece0 92        0.3246     vmlinux                  iput
00000000 91        0.3211     librep.so.9.2.2          (no symbols)
c0146d44 90        0.3175     vmlinux                  proc_base_lookup
c019738c 89        0.3140     vmlinux                  sock_poll
c011eb28 87        0.3070     vmlinux                  get_user_pages
080fb19c 82        0.2893     gdb                      do_my_cleanups
000098c3 82        0.2893     libpthread-0.10.so       __pthread_alt_unlock
c01464f0 80        0.2823     vmlinux                  mem_read
000096bf 78        0.2752     libpthread-0.10.so       __pthread_alt_lock
081b71e0 75        0.2646     gdb                      dyn_string_resize
081b7510 73        0.2576     gdb                      dyn_string_append_char
c01460a4 72        0.2540     vmlinux                  may_ptrace_attach
080de514 70        0.2470     gdb                      target_xfer_memory
08161014 70        0.2470     gdb                      bfd_elf32_slurp_symbol_table
c0110cb0 70        0.2470     vmlinux                  add_wait_queue
...

Re: Terminally slow (75 seconds) on some steps

[Andrew Cagney]

>> > On Tue, 05 Aug 2003 01:20:26 -0400 Andrew Cagney <ac131313@redhat.com>
>> > wrote:
>> > 
> 
>> >> Ok, during library load, GDB has to constantly start/stop the target
>> >> and that slows things down.  Would you be able to oprofile your
> 
>> entire 
> 
>> >> system so its possible to see exactly where that 11 seconds goes?
> 
> 
> OK, I have here running oprofile. I am not sure what sort of report do you
> need. I can copy-n-paste reports to list or publish larger files on my
> website. Here go some simple statistics: run without gdb[1], run inside
> gdb[2], symbol details from gdb run[3]. Oprofile cannot do call graphs, I
> hope you get something out of these numbers.

(I think they are working on the call graph problem :-)

I'm guessing that the second column is seconds.

> [1]
> 
>      2371 30.3352 vmlinux
>       736  9.4166 XFree86
>       729  9.3270 ld-2.3.1.so
>       595  7.6126 libwx_based-2.5.so.0.0.0
>       487  6.2308 libwx_gtkd_core-2.5.so.0.0.0
>       471  6.0261 libc-2.3.1.so
>       454  5.8086 M
> ...
> 
> [2]
> 
>     10567 37.2826 vmlinux
>      8537 30.1203 gdb
>      4402 15.5312 libc-2.3.1.so
>       786  2.7732 ld-2.3.1.so
>       622  2.1945 XFree86
>       511  1.8029 libwx_based-2.5.so.0.0.0
>       455  1.6053 M
> ...

The first suprize is how much time, without GDB, it spends in the kernel 
and the link-loader (ld.so?).  GDB's adding 7 seconds of kernel time 
which isn't too bad but would be useful to know where.

Second is yes, 30s of GDB and 9 of glibc.

> [3]
> 
> 00000000 4402     15.5317     libc-2.3.1.so            (no symbols)
> 080e40e0 1134      4.0011     gdb                      bcache

That's striking.  GDB spent 4s/30s avoiding the creation of duplicate 
strings and other symbols.  The lack of call graph is a shame, useful to 
know from where this was called.  Hmm, assuming no macro debug info 
there are only three calls, all in symtab.c:

- recording the symbol name (linkage name?)
- recording the demangled name
- recording a partial symbol

This is to save a significant amount of memory.  Often two files will 
contain the same partial symbol information (due to headers et.al.).

It's interesting how linkage and demangled names (strings) share the 
same bcache as partial symbol (a struct).  Wonder if separate caches 
would lead to a better hit rate?

I also wonder if the full symbols are making use of the partial symbol 
name bcache.


> c01221cc 1011      3.5671     vmlinux                  file_read_actor
> c01dc330 955       3.3696     vmlinux                  __generic_copy_to_user

Does this copy-to-user appear when GDB isn't present?  Having GDB do 
page sized transfers (which a kernel should do efficiently) is on todo 
lists.

Have you tried `set trust-read-only-sections on'?

> c011f6b8 663       2.3393     vmlinux                  do_anonymous_page
> 00000000 622       2.1946     XFree86                  (no symbols)
> 08134b74 574       2.0253     gdb                      read_partial_die

Ok, so its spending a lot of time reading partial symbols.

> c0118f2c 516       1.8206     vmlinux                  access_process_vm
> 080e3fc0 459       1.6195     gdb                      hash
> 00000000 384       1.3549     libglib-1.2.so.0.0.10    (no symbols)
> c0105370 369       1.3020     vmlinux                  default_idle
> 081b7f7c 360       1.2702     gdb                      htab_find_slot_with_hash
> 08134fe4 307       1.0832     gdb                      read_attribute_value
> 081b8218 292       1.0303     gdb                      htab_hash_string
> c0135408 292       1.0303     vmlinux                  link_path_walk
> c0106d54 283       0.9985     vmlinux                  system_call
> c0147650 273       0.9632     vmlinux                  proc_lookup
> 081351bc 246       0.8680     gdb                      read_attribute
> 00006e48 244       0.8609     ld-2.3.1.so              do_lookup
> 0813195c 240       0.8468     gdb                      add_partial_symbol
> 08135560 237       0.8362     gdb                      read_unsigned_leb128
> c0126294 231       0.8150     vmlinux                  kmem_cache_free
> 00000000 226       0.7974     libX11.so.6.2            (no symbols)
> 00007042 215       0.7586     ld-2.3.1.so              do_lookup_versioned
> c012da38 209       0.7374     vmlinux                  fput
> c0126100 208       0.7339     vmlinux                  kmem_cache_alloc
> 081354e4 204       0.7198     gdb                      read_indirect_string
> c0127834 200       0.7057     vmlinux                  rmqueue
> 0000dc18 188       0.6633     ld-2.3.1.so              strcmp
> c01397f4 185       0.6527     vmlinux                  do_select
> 00002210 168       0.5928     unix.o                   unix_poll
> c013e84c 164       0.5786     vmlinux                  clean_inode
> 00000000 160       0.5645     libgdk-1.2.so.0.9.1      (no symbols)
> 080a43f0 159       0.5610     gdb                      symbol_set_names
> c0127640 155       0.5469     vmlinux                  __free_pages_ok
> 081568b4 147       0.5187     gdb                      bfd_getl32
> 080aa8b0 139       0.4904     gdb                      add_psymbol_to_list
> c0135f24 138       0.4869     vmlinux                  open_namei
> c010fbe4 134       0.4728     vmlinux                  schedule
> 00000000 131       0.4622     libgtk-1.2.so.0.9.1      (no symbols)
> c013cc00 120       0.4234     vmlinux                  dput
> c013d204 117       0.4128     vmlinux                  d_alloc
> c013d3cc 110       0.3881     vmlinux                  d_lookup
> 08134b30 102       0.3599     gdb                      dwarf2_lookup_abbrev
> 081b08e8 101       0.3564     gdb                      demangle_prefix
> 08131800 97        0.3422     gdb                      scan_partial_symbols
> c012db08 97        0.3422     vmlinux                  fget
> 080fbba0 96        0.3387     gdb                      xmmalloc
> 080fd028 93        0.3281     gdb                      strcmp_iw_ordered
> c0146fd0 93        0.3281     vmlinux                  proc_pid_lookup
> c013ece0 92        0.3246     vmlinux                  iput
> 00000000 91        0.3211     librep.so.9.2.2          (no symbols)
> c0146d44 90        0.3175     vmlinux                  proc_base_lookup
> c019738c 89        0.3140     vmlinux                  sock_poll
> c011eb28 87        0.3070     vmlinux                  get_user_pages
> 080fb19c 82        0.2893     gdb                      do_my_cleanups
> 000098c3 82        0.2893     libpthread-0.10.so       __pthread_alt_unlock
> c01464f0 80        0.2823     vmlinux                  mem_read
> 000096bf 78        0.2752     libpthread-0.10.so       __pthread_alt_lock
> 081b71e0 75        0.2646     gdb                      dyn_string_resize
> 081b7510 73        0.2576     gdb                      dyn_string_append_char
> c01460a4 72        0.2540     vmlinux                  may_ptrace_attach
> 080de514 70        0.2470     gdb                      target_xfer_memory
> 08161014 70        0.2470     gdb                      bfd_elf32_slurp_symbol_table
> c0110cb0 70        0.2470     vmlinux                  add_wait_queue
> ...
> 
> 

Re: Terminally slow (75 seconds) on some steps

[Daniel Jacobowitz]

On Fri, Aug 15, 2003 at 06:59:17PM -0400, Andrew Cagney wrote:
> That's striking.  GDB spent 4s/30s avoiding the creation of duplicate 
> strings and other symbols.  The lack of call graph is a shame, useful to 
> know from where this was called.  Hmm, assuming no macro debug info 
> there are only three calls, all in symtab.c:
> 
> - recording the symbol name (linkage name?)
> - recording the demangled name
> - recording a partial symbol
> 
> This is to save a significant amount of memory.  Often two files will 
> contain the same partial symbol information (due to headers et.al.).
> 
> It's interesting how linkage and demangled names (strings) share the 
> same bcache as partial symbol (a struct).  Wonder if separate caches 
> would lead to a better hit rate?
> 
> I also wonder if the full symbols are making use of the partial symbol 
> name bcache.

See SYMBOL_SET_NAMES - I fixed that fairly recently.  Also,
add_psymbol_to_list is how most partial symbols are added; that uses
the same name cache.  If you're talking about the call to bcache in
add_psymbol_with_dem_name_to_list, it's only used by hpread.c.  Fixing
this did in fact improve the hit rate.

> >c011f6b8 663       2.3393     vmlinux                  do_anonymous_page
> >00000000 622       2.1946     XFree86                  (no symbols)
> >08134b74 574       2.0253     gdb                      read_partial_die
> 
> Ok, so its spending a lot of time reading partial symbols.

I've got some plans in this direction... just haven't had time to do
anything about it yet :(

-- 
Daniel Jacobowitz
MontaVista Software                         Debian GNU/Linux Developer

Re: Terminally slow (75 seconds) on some steps

[Andrew Cagney]

> See SYMBOL_SET_NAMES - I fixed that fairly recently.  Also,
> add_psymbol_to_list is how most partial symbols are added; that uses
> the same name cache.  If you're talking about the call to bcache in
> add_psymbol_with_dem_name_to_list, it's only used by hpread.c.  Fixing
> this did in fact improve the hit rate.

Ah.  So the only bcache call is to add the partial symbol to the psymbol 
cache.  That narrows things down a bit.  Wonder if setting 
CHAIN_LENGTH_THRESHOLD lower would help.

>> >c011f6b8 663       2.3393     vmlinux                  do_anonymous_page
>> >00000000 622       2.1946     XFree86                  (no symbols)
>> >08134b74 574       2.0253     gdb                      read_partial_die
> 
>> 
>> Ok, so its spending a lot of time reading partial symbols.
> 
> 
> I've got some plans in this direction... just haven't had time to do
> anything about it yet :(

What about the kernel?  3.5 seconds copying data to the user space is 
suprising.  Can linux, given page sized read requests do it using page 
swapping?

The other question is where in GDB (?) the requests are comming from.  I 
suspect target read, but it could be symbol file related.

Andrew

Re: Terminally slow (75 seconds) on some steps

[Robert Vazan]

On Fri, 15 Aug 2003 18:59:17 -0400 Andrew Cagney <ac131313@redhat.com>
wrote:

> I'm guessing that the second column is seconds.

Sorry, no, I should have included information about this. The second
column is percents. The first column is hit count. I am not sure how much
do you know about oprofile. It has several counters. I have used default
counter that counts Cpu cycles when Cpu is not halted. It makes hit (the
first column) every time the counter reaches zero. I have used default
counter period of 500 000 cycles. One hit is 0.0005 milliseconds on my
gigahertz Pentium III.

> > [1]
> > 
> >      2371 30.3352 vmlinux
> >       736  9.4166 XFree86
> >       729  9.3270 ld-2.3.1.so
> >       595  7.6126 libwx_based-2.5.so.0.0.0
> >       487  6.2308 libwx_gtkd_core-2.5.so.0.0.0
> >       471  6.0261 libc-2.3.1.so
> >       454  5.8086 M
> > ...
> > 
> > [2]
> > 
> >     10567 37.2826 vmlinux
> >      8537 30.1203 gdb
> >      4402 15.5312 libc-2.3.1.so
> >       786  2.7732 ld-2.3.1.so
> >       622  2.1945 XFree86
> >       511  1.8029 libwx_based-2.5.so.0.0.0
> >       455  1.6053 M
> > ...
> 
> The first suprize is how much time, without GDB, it spends in the kernel 
> and the link-loader (ld.so?).  GDB's adding 7 seconds of kernel time 
> which isn't too bad but would be useful to know where.
>
> Second is yes, 30s of GDB and 9 of glibc.

Gdb is adding (10567-2371)*0.0005 = 4 seconds of kernel time along with
8537*0.0005 = 4.3 seconds of gdb time and 2 seconds of libc time.

> > 00000000 4402     15.5317     libc-2.3.1.so            (no symbols)
> > 080e40e0 1134      4.0011     gdb                      bcache
> 
> That's striking.  GDB spent 4s/30s avoiding the creation of duplicate 

0.6/4.3 seconds.

> strings and other symbols.

> > c01221cc 1011      3.5671     vmlinux                  file_read_actor
> > c01dc330 955       3.3696     vmlinux                 
> __generic_copy_to_user
> 
> Does this copy-to-user appear when GDB isn't present?

Yes, but it has only 31 hits.

> Have you tried `set trust-read-only-sections on'?

I'll try this next time I'll be running oprofile.

Btw, I just realized that we are using modules. Our modules are small .so
libraries. There is 27 of them and they are normally loaded at startup.
They take up 500KB each, but I think this is all debug information,
because source is just one .cpp file for each library. Although there is
some (very little) template code (strings, iostreams).

Here's symbol list for non-gdb run, so you have something to compare
against.

00000000 736       9.4166     XFree86                  (no symbols)
00000000 471       6.0261     libc-2.3.1.so            (no symbols)
00000000 451       5.7702     libglib-1.2.so.0.0.10    (no symbols)
00000000 262       3.3521     libX11.so.6.2            (no symbols)
00006e48 248       3.1730     ld-2.3.1.so              do_lookup
00007042 210       2.6868     ld-2.3.1.so              do_lookup_versioned
c01397f4 192       2.4565     vmlinux                  do_select
00002210 175       2.2390     unix.o                   unix_poll
0000dc18 169       2.1622     ld-2.3.1.so              strcmp
00000000 166       2.1238     libgdk-1.2.so.0.9.1      (no symbols)
c0106d54 136       1.7400     vmlinux                  system_call
00000000 133       1.7016     libgtk-1.2.so.0.9.1      (no symbols)
c010fbe4 131       1.6760     vmlinux                  schedule
c012da38 127       1.6249     vmlinux                  fput
c012db08 99        1.2666     vmlinux                  fget
c019738c 91        1.1643     vmlinux                  sock_poll
c0110cfc 89        1.1387     vmlinux                  remove_wait_queue
c0110cb0 83        1.0619     vmlinux                  add_wait_queue
00001d04 83        1.0619     unix.o                   unix_stream_recvmsg
000096bf 81        1.0363     libpthread-0.10.so       __pthread_alt_lock
000098c3 77        0.9852     libpthread-0.10.so       __pthread_alt_unlock
c01399f8 76        0.9724     vmlinux                  sys_select
00000000 69        0.8828     librep.so.9.2.2          (no symbols)
c01396c4 67        0.8572     vmlinux                  __pollwait
c0127640 62        0.7932     vmlinux                  __free_pages_ok
c0127834 61        0.7805     vmlinux                  rmqueue
082c7ce4 59        0.7549     M                        get_bblocks
000068e6 58        0.7421     libpthread-0.10.so       __pthread_mutex_lock
c01261b0 55        0.7037     vmlinux                  kmalloc
000c9fea 48        0.6141     libwx_based-2.5.so.0.0.0 wxStringBase::insert(unsigned int, wxStri
ngBase const&, unsigned int, unsigned int)

Re: Terminally slow (75 seconds) on some steps

[Daniel Jacobowitz]

On Sat, Aug 16, 2003 at 12:36:52PM -0400, Andrew Cagney wrote:
> 
> >See SYMBOL_SET_NAMES - I fixed that fairly recently.  Also,
> >add_psymbol_to_list is how most partial symbols are added; that uses
> >the same name cache.  If you're talking about the call to bcache in
> >add_psymbol_with_dem_name_to_list, it's only used by hpread.c.  Fixing
> >this did in fact improve the hit rate.
> 
> Ah.  So the only bcache call is to add the partial symbol to the psymbol 
> cache.  That narrows things down a bit.  Wonder if setting 
> CHAIN_LENGTH_THRESHOLD lower would help.
> 
> >>>c011f6b8 663       2.3393     vmlinux                  do_anonymous_page
> >>>00000000 622       2.1946     XFree86                  (no symbols)
> >>>08134b74 574       2.0253     gdb                      read_partial_die
> >
> >>
> >>Ok, so its spending a lot of time reading partial symbols.
> >
> >
> >I've got some plans in this direction... just haven't had time to do
> >anything about it yet :(
> 
> What about the kernel?  3.5 seconds copying data to the user space is 
> suprising.  Can linux, given page sized read requests do it using page 
> swapping?
> 
> The other question is where in GDB (?) the requests are comming from.  I 
> suspect target read, but it could be symbol file related.

First of all, we should be using mmap to access symbol files, at least
when there are no relocations.  We probably should be using it even
when there _are_ relocations; however, that will require
re-implementing some simple ELF relocation functions in GDB.  I've long
thought this is necessary.

Second of all, the copy_to_user is likely to come more from ptrace than
from reading.  But that's just a guess really.

-- 
Daniel Jacobowitz
MontaVista Software                         Debian GNU/Linux Developer

Re: Terminally slow (75 seconds) on some steps

[Daniel Berlin]

On Sat, 16 Aug 2003, Daniel Jacobowitz wrote:

> On Sat, Aug 16, 2003 at 12:36:52PM -0400, Andrew Cagney wrote:
> >
> > >See SYMBOL_SET_NAMES - I fixed that fairly recently.  Also,
> > >add_psymbol_to_list is how most partial symbols are added; that uses
> > >the same name cache.  If you're talking about the call to bcache in
> > >add_psymbol_with_dem_name_to_list, it's only used by hpread.c.  Fixing
> > >this did in fact improve the hit rate.
> >
> > Ah.  So the only bcache call is to add the partial symbol to the psymbol
> > cache.  That narrows things down a bit.  Wonder if setting
> > CHAIN_LENGTH_THRESHOLD lower would help.
> >
> > >>>c011f6b8 663       2.3393     vmlinux                  do_anonymous_page
> > >>>00000000 622       2.1946     XFree86                  (no symbols)
> > >>>08134b74 574       2.0253     gdb                      read_partial_die
> > >
> > >>
> > >>Ok, so its spending a lot of time reading partial symbols.
> > >
> > >
> > >I've got some plans in this direction... just haven't had time to do
> > >anything about it yet :(
> >
> > What about the kernel?  3.5 seconds copying data to the user space is
> > suprising.  Can linux, given page sized read requests do it using page
> > swapping?
> >
> > The other question is where in GDB (?) the requests are comming from.  I
> > suspect target read, but it could be symbol file related.
>
> First of all, we should be using mmap to access symbol files, at least
> when there are no relocations.

Been there, done that, was told to do it in BFD.

Re: Terminally slow (75 seconds) on some steps

[Andrew Cagney]

> First of all, we should be using mmap to access symbol files, at least
>> when there are no relocations.
> 
> 
> Been there, done that, was told to do it in BFD.

If there are I/O performances gains to be had, GDB should share them 
with binutils.  Did you look at bfdwin.c (although, in light of recent 
patches to modify bfd so that it can create things from target memory, 
the interface may be heading for review).

Andrew

Re: Terminally slow (75 seconds) on some steps

[Daniel Berlin]

On Monday, August 18, 2003, at 11:04 AM, Andrew Cagney wrote:

>> First of all, we should be using mmap to access symbol files, at least
>>> when there are no relocations.
>> Been there, done that, was told to do it in BFD.
>
> If there are I/O performances gains to be had, GDB should share them 
> with binutils.
Except, you can't.
Even if we were to use the bfd window stuff, binutils wouldn't be using 
it.
So i'm not sure what you mean.
Whether we directly call mmap, or attempt to use the window stuff 
(which is harder to use for us, and not built to do what we want), 
we're still going to be not sharing it with binutils.
IMHO, it makes more sense to add the 3 lines of code necessary to use 
mmap (we need not change anything else, since bfd reads on the mmap'd 
memory will be turned into memory reads as approriate), than to change 
more to use the window stuff.
> Did you look at bfdwin.c (although, in light of recent patches to 
> modify bfd so that it can create things from target memory, the 
> interface may be heading for review).
>
The mmap usage in it not enabled unless you specifically configure it 
on, last i looked.
In fact, last i looked, the window stuff wasn't even turned on unless 
you used --with-mmap.
This may have changed though.
> Andrew
>
>

Re: Terminally slow (75 seconds) on some steps

[Robert Vazan]

On Fri, 15 Aug 2003 18:59:17 -0400 Andrew Cagney <ac131313@redhat.com>
wrote:

> Have you tried `set trust-read-only-sections on'?

It makes no difference.