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

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

[Paul Smith]

Hi all.  Is anyone aware of an issue with a big slowdown running macros
on core files?  I'm not sure if this is related to GCC 4.8 or GDB 7.6,
or what, but I'm seeing a 4x or more slowdown when running macros on
core files from previous releases.

Running against a live process is the same speed as before.

Details: we were building/debugging with the system compiler and
debugger (e.g., GCC 4.5.2 / GDB 7.2).  Speed of macros when dealing with
core files here was acceptable.  FYI, our code is C++ with a small to
moderate number of templates and compiled (in this case) with "-g", and
no optimization.

I wanted to use a new compiler with an encapsulated environment so we
could unify our build toolchain.  I created a separately-installed
version of GCC 4.8.0/binutils 2.23.2.

Then we discovered that trying to use older GDB instances with the
results of this build failed, because they couldn't read the DWARF4
object format generated by GCC 4.8.0.  I thought about dropping back to
an older DWARF format but instead I built GDB 7.6 and added that to our
toolchain.

Now we can debug and everything works well, except that we've noticed
this major slowdown only when debugging corefiles.

The macros are nothing fancy: they just walk through some of our data
structures printing interesting information; for example:

  set $current = $arg0.first
  set $size = 0
  while $current
    printf "node[%u]: id=", $size

    if $current->flags & 1
      printf "*"
    end

    if $current->flags & 2
      printf "^"
    end

    printf "%d, localId=%d, incarnation=%d, type=%d, state=%d\n",
$current->node->nodeId, $current->node->localId,
$current->incarnationNumber, $current->node->nodeType,
$current->node->nodeState
    set $current = $current.next
    set $size++
  end

Against a core file it takes a second or longer per iteration of this
loop!  FWIW, the class this macro operates on is very large and contains
a lot of data per object.

Any ideas?  Is there a handy way to tell where the slowdown is happening
here?  Should we just drop back to DWARF2 or DWARF3 (I haven't checked
if that will help tho)?

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

[Pedro Alves]

On 05/16/2013 08:42 PM, Paul Smith wrote:
> Hi all.  Is anyone aware of an issue with a big slowdown running macros
> on core files?  I'm not sure if this is related to GCC 4.8 or GDB 7.6,
> or what, but I'm seeing a 4x or more slowdown when running macros on
> core files from previous releases.
> 
> Running against a live process is the same speed as before.

Wow.

If you haven't yet, it'd make sense to try process vs core at the
exact same spot:

$ gdb myprogram
(gdb) run
...
(gdb) mymacro
(gdb) gcore mycore
(gdb) quit

$ gdb myprogram -c mycore
(gdb) mymacro

> Against a core file it takes a second or longer per iteration of this
> loop!  FWIW, the class this macro operates on is very large and contains
> a lot of data per object.
> 
> Any ideas?  Is there a handy way to tell where the slowdown is happening
> here?  

I'm really surprised.  If anything, I'd expect cores to be marginally faster.
I suggest git bisecting gdb looking.  Maybe you'll find the culprit
easily that way.

> Should we just drop back to DWARF2 or DWARF3 (I haven't checked
> if that will help tho)?

Ideally no, of course.  Let us know if that indeed helps.
Using DWARF < 4 should make it easier to git bisect the
culprit, as you can then start bisecting before the
patches that added support for DWARF4.

-- 
Pedro Alves

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

[Paul Smith]

On Fri, 2013-05-17 at 11:15 +0100, Pedro Alves wrote:
> > Against a core file it takes a second or longer per iteration of this
> > loop!  FWIW, the class this macro operates on is very large and contains
> > a lot of data per object.
> > 
> > Any ideas?  Is there a handy way to tell where the slowdown is happening
> > here?  
> 
> I'm really surprised.  If anything, I'd expect cores to be marginally faster.
> I suggest git bisecting gdb looking.  Maybe you'll find the culprit
> easily that way.

Sorry for the delay.  Getting a repro case was harder than it seemed
initially... just running "kill -9" on the process wasn't enough, or
didn't crash at the right spot, or something.  We had to induce a
failure through a particular assert().

However, now I have a core file and executable built with my local copy
of GDB 4.8.0.  If I run the macro using a locally-built copy of GDB
7.5.1, then I get this behavior:

  $ time gdb-7.5.1 -c core.30095 -x macros.gdb myprog \
      -ex "frame 4" -ex "ptracelog master->traceLog" -ex "q"
   ...prints 200 trace log lines...
  real    0m2.811s
  user    0m2.768s
  sys     0m0.028s

so that's good stuff.

Now I try it with GDB 7.6, compiled locally using the identical
configure/etc. commands, and I get this behavior:

  $ time gdb-7.6 -c core.30095 -x macros.gdb myprog \
      -ex "frame 4" -ex "ptracelog master->traceLog" -ex "q"
   ...prints 200 trace log lines...
  real    11m51.113s
  user    11m46.324s
  sys     0m2.168s

That's... not as good :-p.

I've just got this case working now, so I'll look into what's going on
here more.

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

[Paul Smith]

On Wed, 2013-05-22 at 14:45 -0400, Paul Smith wrote:
> I've just got this case working now, so I'll look into what's going on
> here more.

OK, some quick info from strace: the fast GDB does about 400 system
calls for the first iteration of the loop, in 0.024 seconds.  It does
124 lseek(), 177 read(), and 101 rt_sigprocmask() system calls.

The slow GDB does 20773 system calls in 4.4 seconds for the first
iteration.  It does 6914 lseek(), 13757 read(), and 101 rt_sigprocmask()
system calls (plus the write of the results).

The interesting thing is both versions are constantly seeking and
reading to exactly the same location, over and over again.  However GDB
4.6 does it many times more than GDB 7.5.1.  For example, I get this
combo:

14:51:34.423582 lseek(7, 26763264, SEEK_SET) = 26763264 <0.000004>
14:51:34.423609 read(7, "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"..., 4096) = 4096 <0.000015>

6838 times during the slow run (exact same offset value, exact same read
request and response), and this one:

14:52:16.842408 lseek(14, 26763264, SEEK_SET) = 26763264 <0.000004>
14:52:16.842435 read(14, "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"..., 4096) = 4096 <0.000004>

48 times during the fast run.  BTW I checked and those FDs are for the
executable in both runs.  I'm not sure why they're opened in a different
order.

Seems like it's time to do some test builds against the git tree.

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

[Tom Tromey]

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

Tom

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

[Paul Smith]

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'll see what I can do.  Meantime, git bisect declares this commit to be
the one that introduced the slow behavior:

677b1bfabd372790dca4dad32fcb05dd77658728 is the first bad commit
commit 677b1bfabd372790dca4dad32fcb05dd77658728
Author: Keith Seitz <keiths@redhat.com>
Date:   Fri Nov 16 20:54:28 2012 +0000

        PR c++/13615
        * cp-namespace.c (cp_lookup_symbol_in_namespace): Add SEARCH
        parameter and pass it to lookup_symbol_file.
        (cp_lookup_symbol_imports): Tell cp_lookup_symbol_in_namespace
        to search base classes.
        (cp_lookup_symbol_namespace): Likewise.
        (lookup_namespace_scope): Likewise.
        (lookup_symbol_file): Add SEARCH parameter.
        If SEARCH is non-zero and no symbol is found, lookup the class
        and call cp_lookup_nested_symbol.
        (find_symbol_in_baseclass): New function.
        (cp_lookup_nested_symbol): Do not let
        cp_lookup_symbol_in_namespace search through base classes.
        Do that later when there is no global symbol match.
    
        PR c++/13615
        * gdb.cp/baseenum.cc: New file.
        * gdb.cp/baseenum.exp: New file.
        * gdb.cp/derivation.cc (A): Add copyright.
        Add a typedef.
        (B): Use A::value_type instead of int.  Change all references.
        (D): Use value_type instead of int.  Change all references.
        (E): Likewise.
        (F); Likewise.
        (Z): New class.
        (ZZ): New class.
        (N, Base, Derived): New namespace and classes.
        (main): Add instances of Z and ZZ.
        Make sure all symbols from N are kept.
        * gdb.cp/derivation.exp: Update typedef changes in tests.
        Add tests for class typedefs both before and after starting
        the inferior.
        Add tests for searching for a typedef while stopped in a
        method.

:040000 040000 f605271943211b58d6946f8f837053aac8e2b185
0afb509700f9a0d88f26fb498615c9c906bfeb1d M      gdb

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

[Paul Smith]

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.

FYI this seems pretty real so I filed a bug:

http://sourceware.org/bugzilla/show_bug.cgi?id=15519

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

[Paul Smith]

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

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

[Doug Evans]

On Wed, May 22, 2013 at 4:14 PM, Paul Smith <psmith@gnu.org> wrote:
> On Wed, 2013-05-22 at 14:12 -0600, Tom Tromey wrote:
> 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

Looks rather familiar.  :-)

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

[Paul Smith]

On Wed, 2013-05-22 at 19:44 -0700, Doug Evans wrote:
> On Wed, May 22, 2013 at 4:14 PM, Paul Smith <psmith@gnu.org> wrote:
> > On Wed, 2013-05-22 at 14:12 -0600, Tom Tromey wrote:
> > 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
> 
> Looks rather familiar.  :-)

Hi Doug; I'm not sure what that means; is there already a bug filed
about this?  Is it a known issue?

I tested with the latest code on master in the Git repo earlier today
and saw the same slow behavior, so it's not been fixed since 7.6 was
released.

Cheers!

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

[Paul Smith]

On Wed, 2013-05-22 at 19:14 -0400, Paul Smith wrote:
> 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:
> 
> 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 :-).
> 
> At this point I'm out of ideas.  Please let me know if there's more
> you'd like me to do...

Hi all.  I think I'm going to have to back up to GDB 7.5.1; the pain is
too great, when it does happen.

I'll maintain the core file and test setup, so let me know if there's
anything else I can do to help resolve this issue, or if there are
patches you'd like me to try.

Cheers!

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

[Doug Evans]

On Wed, May 22, 2013 at 9:41 PM, Paul Smith <psmith@gnu.org> wrote:
> On Wed, 2013-05-22 at 19:44 -0700, Doug Evans wrote:
>> On Wed, May 22, 2013 at 4:14 PM, Paul Smith <psmith@gnu.org> wrote:
>> > On Wed, 2013-05-22 at 14:12 -0600, Tom Tromey wrote:
>> > 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
>>
>> Looks rather familiar.  :-)
>
> Hi Doug; I'm not sure what that means; is there already a bug filed
> about this?  Is it a known issue?
>
> I tested with the latest code on master in the Git repo earlier today
> and saw the same slow behavior, so it's not been fixed since 7.6 was
> released.

Hi.
That was more an off-the-cuff comment as I've done a ton of profiling
and reading of gdb's symbol table code (one can only do it in stages -
it can get quite depressing).
And I can't offhand explain why you *only* see the slowdown with a
core file and not with a live executable.

I wasn't aware of the problems with the 12/11/16 patch you found.
I've submitted a minor improvement - IMO the real fix will involve a
lot more effort - gdb's symbol handling is obtuse enough that it's
easy to introduce performance regressions or even overlook basic
performance problems.

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

[Paul Smith]

On Tue, 2013-05-28 at 10:10 -0700, Doug Evans wrote:
> And I can't offhand explain why you *only* see the slowdown with a
> core file and not with a live executable.

Well, just because we haven't found a way to make it happen with live
debugging doesn't mean it couldn't :-).

Since it only seems to happen with cores generated in a specific way
(that is, not all core dumps show the issue), I assume that whatever
thing is happening in this core file is not happening with live
debugging, or at least we haven't found a way to trigger it.

> I wasn't aware of the problems with the 12/11/16 patch you found.
> I've submitted a minor improvement - IMO the real fix will involve a
> lot more effort - gdb's symbol handling is obtuse enough that it's
> easy to introduce performance regressions or even overlook basic
> performance problems.

I'll try the latest Git to see if it makes a difference.

> Is it possible to send me the binary+core+scripts+session-log?
> [Assuming it's legally possible, there are a few services I know of
> for sending large files.]

I think it should be OK: sending the core and binary, plus the macro, is
enough to show the problem.  I'll check and let you know.

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

[Doug Evans]

On Tue, May 28, 2013 at 10:32 AM, Paul Smith <psmith@gnu.org> wrote:
> On Tue, 2013-05-28 at 10:10 -0700, Doug Evans wrote:
>> And I can't offhand explain why you *only* see the slowdown with a
>> core file and not with a live executable.
>
> Well, just because we haven't found a way to make it happen with live
> debugging doesn't mean it couldn't :-).

Indeed.

>> I wasn't aware of the problems with the 12/11/16 patch you found.
>> I've submitted a minor improvement - IMO the real fix will involve a
>> lot more effort - gdb's symbol handling is obtuse enough that it's
>> easy to introduce performance regressions or even overlook basic
>> performance problems.
>
> I'll try the latest Git to see if it makes a difference.

I'd be curious for before/after data with this patch:

http://sourceware.org/ml/gdb-patches/2013-05/msg00964.html

I doubt it fixes everything, or even a lot of it.
But data is good.

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

[Paul Smith]

On Tue, 2013-05-28 at 10:40 -0700, Doug Evans wrote:
> > I'll try the latest Git to see if it makes a difference.
> 
> I'd be curious for before/after data with this patch:
> 
> http://sourceware.org/ml/gdb-patches/2013-05/msg00964.html
> 
> I doubt it fixes everything, or even a lot of it.

I didn't realize that wasn't pushed yet.  In any event I tried the
latest content of Git and then I also tried with the above patch
applied, and there was no appreciable improvement (I didn't do an
in-depth analysis of exactly how many times various functions were
called to see if it improved, but the iterations of the macro continued
to take multiple seconds where they take fractions of a second with
7.5.1).

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

[Doug Evans]

On Tue, May 28, 2013 at 10:53 AM, Paul Smith <psmith@gnu.org> wrote:
> On Tue, 2013-05-28 at 10:40 -0700, Doug Evans wrote:
>> > I'll try the latest Git to see if it makes a difference.
>>
>> I'd be curious for before/after data with this patch:
>>
>> http://sourceware.org/ml/gdb-patches/2013-05/msg00964.html
>>
>> I doubt it fixes everything, or even a lot of it.
>
> I didn't realize that wasn't pushed yet.  In any event I tried the
> latest content of Git and then I also tried with the above patch
> applied, and there was no appreciable improvement (I didn't do an
> in-depth analysis of exactly how many times various functions were
> called to see if it improved, but the iterations of the macro continued
> to take multiple seconds where they take fractions of a second with
> 7.5.1).

Not unexpected, but thanks for the data.