This is the mail archive of the
gdb@sourceware.org
mailing list for the GDB project.
Re: [GDB 7.6/GCC 4.8.0] Slowdown in GDB macro processing for cores?
- From: Paul Smith <psmith at gnu dot org>
- To: Tom Tromey <tromey at redhat dot com>
- Cc: Pedro Alves <palves at redhat dot com>, gdb at sourceware dot org
- Date: Wed, 22 May 2013 19:14:04 -0400
- Subject: Re: [GDB 7.6/GCC 4.8.0] Slowdown in GDB macro processing for cores?
- References: <1368733335 dot 4101 dot 743 dot camel at pdsdesk> <51960329 dot 2010802 at redhat dot com> <1369248335 dot 7209 dot 151 dot camel at homebase> <1369250399 dot 7209 dot 164 dot camel at homebase> <87wqqqg4e2 dot fsf at fleche dot redhat dot com>
- Reply-to: psmith at gnu dot org
On Wed, 2013-05-22 at 14:12 -0600, Tom Tromey wrote:
> >>>>> "Paul" == Paul Smith <psmith@gnu.org> 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 <cycle 1> [2585]
69372301 lookup_symbol_aux_psymtabs <cycle 1> [10]
[4] 82.2 14.26 34.59 69374700 lookup_partial_symbol <cycle 1> [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 <cycle 1> [150]
-----------------------------------------------
0.00 0.00 6/819477261 lookup_symbol_aux_psymtabs <cycle 1> [10]
0.00 0.00 60/819477261 new_symbol_full <cycle 1> [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 <cycle 1> [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 <cycle 1> [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 <cycle 1> [370]
0.00 0.00 14179/784950557 check_field <cycle 1> [311]
0.02 0.00 1186966/784950557 iter_match_first_hashed [50]
14.11 0.00 783742926/784950557 lookup_partial_symbol <cycle 1> [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...