Re: Terminally slow (75 seconds) on some steps

Robert Vazan
2003-08-16T16:38:54Z

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)