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

[Paul Smith <psmith@gnu.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...