Re: [GDB 7.6/GCC 4.8.0] Slowdown in GDB macro processing for cores?

Paul Smith
2013-05-22T23:14:09Z

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...