From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 21287 invoked by alias); 16 Aug 2003 16:38:54 -0000 Mailing-List: contact gdb-help@sources.redhat.com; run by ezmlm Precedence: bulk List-Subscribe: List-Archive: List-Post: List-Help: , Sender: gdb-owner@sources.redhat.com Received: (qmail 21276 invoked from network); 16 Aug 2003 16:38:49 -0000 Received: from unknown (HELO ns2.dialtelecom.sk) (217.67.16.3) by sources.redhat.com with SMTP; 16 Aug 2003 16:38:49 -0000 Received: (qmail 26384 invoked from network); 16 Aug 2003 16:37:55 -0000 Received: from unknown (HELO pcw2k69.energoinfo.sk) (81.0.194.199) by ns2.dialtelecom.sk with SMTP; 16 Aug 2003 16:37:55 -0000 Received: from main by pcw2k69.energoinfo.sk with local (Exim 3.35 #1 (Debian)) id 19o44f-0000Bj-00 for ; Sat, 16 Aug 2003 18:38:41 +0200 Received: by pcw2k69.energoinfo.sk (tmda-inject, from uid 1000); Sat, 16 Aug 2003 18:38:41 +0200 Date: Sat, 16 Aug 2003 16:38:00 -0000 Subject: Re: Terminally slow (75 seconds) on some steps To: Andrew Cagney cc: gdb@sources.redhat.com Message-ID: MIME-Version: 1.0 Content-Type: TEXT/PLAIN; CHARSET=US-ASCII Content-Disposition: INLINE References: <1057999221.6815.ezmlm@sources.redhat.com> <3F16D022.30209@redhat.com> <3F186D0B.5020902@redhat.com> <3F1BF6D4.6090801@redhat.com> <3F2F3E9A.6050403@redhat.com> <3F2FF8F5.6070007@redhat.com> <3F3D65C5.2070005@redhat.com> In-Reply-To: <3F3D65C5.2070005@redhat.com> From: Robert Vazan X-Delivery-Agent: TMDA/0.75 (Ponder) X-SW-Source: 2003-08/txt/msg00171.txt.bz2 On Fri, 15 Aug 2003 18:59:17 -0400 Andrew Cagney 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)