From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 11931 invoked by alias); 22 May 2013 23:14:09 -0000 Mailing-List: contact gdb-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: gdb-owner@sourceware.org Received: (qmail 11916 invoked by uid 89); 22 May 2013 23:14:09 -0000 X-Spam-SWARE-Status: No, score=-2.2 required=5.0 tests=AWL,BAYES_00,KHOP_THREADED,RCVD_IN_DNSWL_NONE,RCVD_IN_HOSTKARMA_YE,SPF_SOFTFAIL autolearn=no version=3.3.1 Received: from oproxy9.bluehost.com (HELO oproxy9.bluehost.com) (69.89.24.6) by sourceware.org (qpsmtpd/0.84/v0.84-167-ge50287c) with SMTP; Wed, 22 May 2013 23:14:08 +0000 Received: (qmail 31878 invoked by uid 0); 22 May 2013 23:14:06 -0000 Received: from unknown (HELO box531.bluehost.com) (74.220.219.131) by oproxy9.bluehost.com with SMTP; 22 May 2013 23:14:06 -0000 Received: from [146.115.71.23] (port=32970 helo=[172.31.1.206]) by box531.bluehost.com with esmtpsa (SSLv3:CAMELLIA256-SHA:256) (Exim 4.80) (envelope-from ) id 1UfIEQ-0006cT-Ak; Wed, 22 May 2013 17:14:06 -0600 Message-ID: <1369264444.7209.184.camel@homebase> Subject: Re: [GDB 7.6/GCC 4.8.0] Slowdown in GDB macro processing for cores? From: Paul Smith Reply-To: psmith@gnu.org To: Tom Tromey Cc: Pedro Alves , gdb@sourceware.org Date: Wed, 22 May 2013 23:14:00 -0000 In-Reply-To: <87wqqqg4e2.fsf@fleche.redhat.com> References: <1368733335.4101.743.camel@pdsdesk> <51960329.2010802@redhat.com> <1369248335.7209.151.camel@homebase> <1369250399.7209.164.camel@homebase> <87wqqqg4e2.fsf@fleche.redhat.com> Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: 7bit Mime-Version: 1.0 X-Identified-User: {678:box531.bluehost.com:madscie1:mad-scientist.us} {sentby:smtp auth 146.115.71.23 authed with paul@mad-scientist.us} X-SW-Source: 2013-05/txt/msg00109.txt.bz2 On Wed, 2013-05-22 at 14:12 -0600, Tom Tromey wrote: > >>>>> "Paul" == Paul Smith writes: > > Paul> The interesting thing is both versions are constantly seeking and > Paul> reading to exactly the same location, over and over again. However GDB > Paul> 4.6 does it many times more than GDB 7.5.1. For example, I get this > Paul> combo: > > Paul> 14:51:34.423582 lseek(7, 26763264, SEEK_SET) = 26763264 <0.000004> > Paul> 14:51:34.423609 read(7, > Paul> "P\361\236\0\0\0\0\0`\361\236\0\0\0\0\0p\361\236\0\0\0\0\0\200\361\236\0\0\0\0\0"..., > Paul> 4096) = 4096 <0.000015> > > A backtrace from one of these seeks or reads might be useful. > > Or, gprof. I have gmon.out from the last "fast" commit and the first "slow" commit; I reduced the number of iterations in the macro to 4 (instead of 200) so the slow one would not take so long :-). Here are the top 10 users in the fast instance of GDB: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls ms/call ms/call name 5.34 0.07 0.07 1160206 0.00 0.00 hash_continue 4.58 0.13 0.06 311421 0.00 0.00 htab_hash_string 3.82 0.18 0.05 1244860 0.00 0.00 strcmp_iw 3.82 0.23 0.05 548 0.09 0.10 dwarf_decode_lines_1 3.82 0.28 0.05 540 0.09 0.79 load_partial_dies 3.05 0.32 0.04 1686943 0.00 0.00 symbol_get_demangled_name 3.05 0.36 0.04 435700 0.00 0.00 strcmp_iw_ordered 3.05 0.40 0.04 370289 0.00 0.00 bfd_getl64 3.05 0.44 0.04 compare_minimal_symbols 2.29 0.47 0.03 1492880 0.00 0.00 read_unsigned_leb128 And the top 10 users in the slow instance: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls ms/call ms/call name 23.99 14.26 14.26 69374700 0.00 0.00 lookup_partial_symbol 23.77 28.39 14.13 784950557 0.00 0.00 strcmp_iw 11.74 35.37 6.98 763482775 0.00 0.00 symbol_get_demangled_name 7.23 39.67 4.30 819480663 0.00 0.00 symbol_natural_name 7.22 43.96 4.29 373483 0.01 0.01 lookup_symbol_aux_psymtabs 5.60 47.29 3.33 777569558 0.00 0.00 symbol_matches_domain 4.98 50.25 2.96 819477261 0.00 0.00 symbol_search_name 2.46 51.71 1.46 34366788 0.00 0.00 strcmp_iw_ordered 1.51 52.61 0.90 4 225.00 225.00 fprintf_symbol_filtered 1.46 53.48 0.87 15316453 0.00 0.00 xstrdup For comparison, the top symbol in the slow instance (lookup_partial_symbol) is 31st on the list in the fast instance. FYI here are the call graphs for lookup_partial_symbol and its main callers: ----------------------------------------------- 2399 find_symbol_file_from_partial [2585] 69372301 lookup_symbol_aux_psymtabs [10] [4] 82.2 14.26 34.59 69374700 lookup_partial_symbol [4] 2.95 11.26 818053917/819477261 symbol_search_name [5] 14.11 0.00 783742926/784950557 strcmp_iw [6] 3.33 0.00 777559148/777569558 symbol_matches_domain [11] 1.46 0.00 34310991/34366788 strcmp_iw_ordered [14] 0.16 0.91 15300997/15300997 psymtab_search_name [18] 0.04 0.36 15300997/15366819 make_cleanup [38] 15300997 do_cleanups [150] ----------------------------------------------- 0.00 0.00 6/819477261 lookup_symbol_aux_psymtabs [10] 0.00 0.00 60/819477261 new_symbol_full [24] 0.00 0.00 353/819477261 lookup_minimal_symbol [368] 0.00 0.00 366/819477261 iter_match_next_linear [504] 0.00 0.00 8382/819477261 insert_symbol_hashed [210] 0.00 0.00 22719/819477261 add_minsym_to_demangled_hash_table [121] 0.00 0.00 92898/819477261 build_minimal_symbol_hash_tables [75] 0.00 0.00 111594/819477261 compare_psymbols [126] 0.00 0.02 1186966/819477261 iter_match_first_hashed [50] 2.95 11.26 818053917/819477261 lookup_partial_symbol [4] [5] 24.0 2.96 11.28 819477261 symbol_search_name [5] 4.30 6.98 819477261/819480663 symbol_natural_name [7] ----------------------------------------------- 0.00 0.00 6/784950557 lookup_symbol_aux_psymtabs [10] 0.00 0.00 353/784950557 lookup_minimal_symbol [368] 0.00 0.00 366/784950557 iter_match_next_linear [504] 0.00 0.00 5761/784950557 do_search_struct_field [370] 0.00 0.00 14179/784950557 check_field [311] 0.02 0.00 1186966/784950557 iter_match_first_hashed [50] 14.11 0.00 783742926/784950557 lookup_partial_symbol [4] [6] 23.8 14.13 0.00 784950557 strcmp_iw [6] ----------------------------------------------- I will attach the full gprof outputs from both runs to the bug (compressed). At this point I'm out of ideas. Please let me know if there's more you'd like me to do...