* Terminally slow (75 seconds) on some steps [not found] <1057999221.6815.ezmlm@sources.redhat.com> @ 2003-07-12 9:03 ` Robert Vazan 2003-07-17 16:34 ` Andrew Cagney 0 siblings, 1 reply; 20+ messages in thread From: Robert Vazan @ 2003-07-12 9:03 UTC (permalink / raw) To: gdb 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. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-07-12 9:03 ` Terminally slow (75 seconds) on some steps Robert Vazan @ 2003-07-17 16:34 ` Andrew Cagney 2003-07-18 13:06 ` Robert Vazan 0 siblings, 1 reply; 20+ messages in thread From: Andrew Cagney @ 2003-07-17 16:34 UTC (permalink / raw) To: Robert Vazan; +Cc: gdb > 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/) ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-07-17 16:34 ` Andrew Cagney @ 2003-07-18 13:06 ` Robert Vazan 2003-07-18 21:56 ` Andrew Cagney 0 siblings, 1 reply; 20+ messages in thread From: Robert Vazan @ 2003-07-18 13:06 UTC (permalink / raw) To: Andrew Cagney; +Cc: gdb 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. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-07-18 13:06 ` Robert Vazan @ 2003-07-18 21:56 ` Andrew Cagney 2003-07-19 11:29 ` Robert Vazan 0 siblings, 1 reply; 20+ messages in thread From: Andrew Cagney @ 2003-07-18 21:56 UTC (permalink / raw) To: Robert Vazan; +Cc: gdb > 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 ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-07-18 21:56 ` Andrew Cagney @ 2003-07-19 11:29 ` Robert Vazan 2003-07-21 14:21 ` Andrew Cagney 0 siblings, 1 reply; 20+ messages in thread From: Robert Vazan @ 2003-07-19 11:29 UTC (permalink / raw) To: Andrew Cagney; +Cc: gdb 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. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-07-19 11:29 ` Robert Vazan @ 2003-07-21 14:21 ` Andrew Cagney 2003-07-21 17:38 ` Robert Vazan 0 siblings, 1 reply; 20+ messages in thread From: Andrew Cagney @ 2003-07-21 14:21 UTC (permalink / raw) To: Robert Vazan; +Cc: gdb > 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 ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-07-21 14:21 ` Andrew Cagney @ 2003-07-21 17:38 ` Robert Vazan 2003-08-05 5:20 ` Andrew Cagney 0 siblings, 1 reply; 20+ messages in thread From: Robert Vazan @ 2003-07-21 17:38 UTC (permalink / raw) To: Andrew Cagney; +Cc: gdb 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. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-07-21 17:38 ` Robert Vazan @ 2003-08-05 5:20 ` Andrew Cagney 2003-08-05 18:04 ` Robert Vazan 0 siblings, 1 reply; 20+ messages in thread From: Andrew Cagney @ 2003-08-05 5:20 UTC (permalink / raw) To: Robert Vazan; +Cc: gdb > 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 ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-05 5:20 ` Andrew Cagney @ 2003-08-05 18:04 ` Robert Vazan 2003-08-05 18:35 ` Andrew Cagney 0 siblings, 1 reply; 20+ messages in thread From: Robert Vazan @ 2003-08-05 18:04 UTC (permalink / raw) To: Andrew Cagney; +Cc: gdb 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"? ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-05 18:04 ` Robert Vazan @ 2003-08-05 18:35 ` Andrew Cagney 2003-08-14 12:05 ` Robert Vazan 0 siblings, 1 reply; 20+ messages in thread From: Andrew Cagney @ 2003-08-05 18:35 UTC (permalink / raw) To: Robert Vazan; +Cc: gdb 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"? > > ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-05 18:35 ` Andrew Cagney @ 2003-08-14 12:05 ` Robert Vazan 2003-08-15 22:59 ` Andrew Cagney 0 siblings, 1 reply; 20+ messages in thread From: Robert Vazan @ 2003-08-14 12:05 UTC (permalink / raw) To: Andrew Cagney; +Cc: gdb > > 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 ... ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-14 12:05 ` Robert Vazan @ 2003-08-15 22:59 ` Andrew Cagney 2003-08-16 15:11 ` Daniel Jacobowitz ` (2 more replies) 0 siblings, 3 replies; 20+ messages in thread From: Andrew Cagney @ 2003-08-15 22:59 UTC (permalink / raw) To: Robert Vazan; +Cc: gdb >> > 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 > ... > > ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-15 22:59 ` Andrew Cagney @ 2003-08-16 15:11 ` Daniel Jacobowitz 2003-08-16 16:36 ` Andrew Cagney 2003-08-16 16:38 ` Robert Vazan 2003-08-20 16:12 ` Robert Vazan 2 siblings, 1 reply; 20+ messages in thread From: Daniel Jacobowitz @ 2003-08-16 15:11 UTC (permalink / raw) To: gdb 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 ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-16 15:11 ` Daniel Jacobowitz @ 2003-08-16 16:36 ` Andrew Cagney 2003-08-16 16:41 ` Daniel Jacobowitz 0 siblings, 1 reply; 20+ messages in thread From: Andrew Cagney @ 2003-08-16 16:36 UTC (permalink / raw) To: Daniel Jacobowitz; +Cc: gdb > 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 ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-16 16:36 ` Andrew Cagney @ 2003-08-16 16:41 ` Daniel Jacobowitz 2003-08-17 3:29 ` Daniel Berlin 0 siblings, 1 reply; 20+ messages in thread From: Daniel Jacobowitz @ 2003-08-16 16:41 UTC (permalink / raw) To: Andrew Cagney; +Cc: gdb 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 ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-16 16:41 ` Daniel Jacobowitz @ 2003-08-17 3:29 ` Daniel Berlin 2003-08-18 15:05 ` Andrew Cagney 0 siblings, 1 reply; 20+ messages in thread From: Daniel Berlin @ 2003-08-17 3:29 UTC (permalink / raw) To: Daniel Jacobowitz; +Cc: Andrew Cagney, gdb 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. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-17 3:29 ` Daniel Berlin @ 2003-08-18 15:05 ` Andrew Cagney 2003-08-18 16:15 ` Daniel Berlin 0 siblings, 1 reply; 20+ messages in thread From: Andrew Cagney @ 2003-08-18 15:05 UTC (permalink / raw) To: Daniel Berlin; +Cc: Daniel Jacobowitz, gdb > 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 ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-18 15:05 ` Andrew Cagney @ 2003-08-18 16:15 ` Daniel Berlin 0 siblings, 0 replies; 20+ messages in thread From: Daniel Berlin @ 2003-08-18 16:15 UTC (permalink / raw) To: Andrew Cagney; +Cc: Daniel Jacobowitz, gdb 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 > > ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-15 22:59 ` Andrew Cagney 2003-08-16 15:11 ` Daniel Jacobowitz @ 2003-08-16 16:38 ` Robert Vazan 2003-08-20 16:12 ` Robert Vazan 2 siblings, 0 replies; 20+ messages in thread From: Robert Vazan @ 2003-08-16 16:38 UTC (permalink / raw) To: Andrew Cagney; +Cc: gdb 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) ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: Terminally slow (75 seconds) on some steps 2003-08-15 22:59 ` Andrew Cagney 2003-08-16 15:11 ` Daniel Jacobowitz 2003-08-16 16:38 ` Robert Vazan @ 2003-08-20 16:12 ` Robert Vazan 2 siblings, 0 replies; 20+ messages in thread From: Robert Vazan @ 2003-08-20 16:12 UTC (permalink / raw) To: Andrew Cagney; +Cc: gdb 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. ^ permalink raw reply [flat|nested] 20+ messages in thread
end of thread, other threads:[~2003-08-20 16:12 UTC | newest] Thread overview: 20+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- [not found] <1057999221.6815.ezmlm@sources.redhat.com> 2003-07-12 9:03 ` Terminally slow (75 seconds) on some steps Robert Vazan 2003-07-17 16:34 ` Andrew Cagney 2003-07-18 13:06 ` Robert Vazan 2003-07-18 21:56 ` Andrew Cagney 2003-07-19 11:29 ` Robert Vazan 2003-07-21 14:21 ` Andrew Cagney 2003-07-21 17:38 ` Robert Vazan 2003-08-05 5:20 ` Andrew Cagney 2003-08-05 18:04 ` Robert Vazan 2003-08-05 18:35 ` Andrew Cagney 2003-08-14 12:05 ` Robert Vazan 2003-08-15 22:59 ` Andrew Cagney 2003-08-16 15:11 ` Daniel Jacobowitz 2003-08-16 16:36 ` Andrew Cagney 2003-08-16 16:41 ` Daniel Jacobowitz 2003-08-17 3:29 ` Daniel Berlin 2003-08-18 15:05 ` Andrew Cagney 2003-08-18 16:15 ` Daniel Berlin 2003-08-16 16:38 ` Robert Vazan 2003-08-20 16:12 ` Robert Vazan
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).