quadratic slowdown in 'where' command

quadratic slowdown in 'where' command

[Paul Pluzhnikov]

Greetings,

While debugging something else, I noticed extreme slowdown of
'where' command for a deeply recursive stack trace, and was able
to reproduce it on a small example (below). AFAICT, this is related
to this change:

  2008-04-30  Daniel Jacobowitz  <dan@codesourcery.com>

	* valops.c (value_fetch_lazy): Handle both memory and register
	lvals.

Here is the timing info (doubling size quadruples time):

$ time gdb -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex where -ex quit --args ./deep  2500  > /dev/null

real    0m0.617s
user    0m0.575s
sys     0m0.034s

$ time gdb -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex where -ex quit --args ./deep  5000  > /dev/null

real    0m2.121s
user    0m2.049s
sys     0m0.048s

$ time gdb -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex where -ex quit --args ./deep  10000  > /dev/null

real    0m9.140s
user    0m8.991s
sys     0m0.077s

$ time gdb -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex where -ex quit --args ./deep  20000  > /dev/null

real    0m47.940s
user    0m47.543s
sys     0m0.182s

I used current CVS head: GNU gdb (GDB) 6.8.50.20081104-cvs ...

The results are also rather interesting: running 'where' by hand
shows that GDB prints all levels except the last one rather fast,
but then 'freezes' for a long time printing the last level.

This can be seen in dramatic difference between these timings:

$ time gdb64-cvs -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex 'where 10004' -ex quit --args ./deep  10000  > /dev/null

real    0m0.438s
user    0m0.353s
sys     0m0.073s

$ time gdb64-cvs -nx -ex 'set height 0' -ex 'set confirm off' -ex run -ex 'where 10005' -ex quit --args ./deep  10000  > /dev/null

real    0m9.083s
user    0m8.953s
sys     0m0.067s

I looked at "what's different WRT the last frame" in valops.c,
but couldn't spot anything obvious :-(


Finally, here is the test case:

--- cut --- deep.c ---
// Compile with GCC-4.3.1: "gcc -g deep.c -o deep -O2".
// Note: -O2 is required to see the bad behavior.
//
// The test case itself is nonsense, crafted to prevent
// GCC from optimizing too much.

#include <stdlib.h>

struct Node 
{
  struct Node *l;
  struct Node *r;
  int x;
};

int limit;
int visit (struct Node *n)
{
  int ll, rr;
  if (!n) return 0;
  if (limit < n->x)
    abort ();
  n->x += 1;
  ll = visit (n->l);
  rr = visit (n->r);
  return ll + rr + n->x;
}

int main (int argc, char *argv[])
{
  struct Node n;

  limit = 1000;
  if (1 < argc)
    limit = atoi (argv[1]);

  n.x = 0;
  n.l = &n;
  n.r = &n;
  return visit (&n);
}
--- cut --- deep.c ---


--
Paul Pluzhnikov

Re: quadratic slowdown in 'where' command

[Tom Tromey]

>>>>> "Paul" == Paul Pluzhnikov <ppluzhnikov@google.com> writes:

Paul> While debugging something else, I noticed extreme slowdown of
Paul> 'where' command for a deeply recursive stack trace, and was able
Paul> to reproduce it on a small example (below).

FWIW, I'm able to reproduce this as well.

Paul> The results are also rather interesting: running 'where' by hand
Paul> shows that GDB prints all levels except the last one rather fast,
Paul> but then 'freezes' for a long time printing the last level.

I wasn't able to reproduce this.  That is, I ran the test a number of
times, and sometimes I saw this effect, but sometimes I did not.

Could you file this in bugzilla?

Tom