Massive slowdown printing values in gdb-7.1

Massive slowdown printing values in gdb-7.1

[Srinath Avadhanula]

Hi,

I have been testing gdb 7.1 lately and have noticed that under some
circumstances (which I have been unable to reproduce with a simple
program), it is taking extremely long (~ 30 seconds) to print a simple
expreession such as

(gdb) p s->graph

where s is a symbol of type "SubsystemBlock" and graph is a sub-field
of the structure SubsystemBlock. This used to be pretty much
instantaneous in gdb 6.8.

I tried the sampling method described at [1] to find out where gdb
might be spending the most time. I found out that the five times I
interrupted gdb in the middle of the printing, I got almost the same
stack:

----------------- %< ---------------------------
#0  0x00000000004556d5 in strcmp_iw_ordered (string1=0x29eda318
"pir::PathBalanceChecker::visit(pir::BlockComp&)",
string2=0x7fffab13ade0 "getenv::graph") at utils.c:2740
#1  0x000000000050ce85 in lookup_partial_symbol (pst=<value optimized
out>, name=0x7fffab13ade0 "getenv::graph", linkage_name=0x0,
global=<value optimized out>, domain=VAR_DOMAIN) at symtab.c:1801
#2  0x000000000050d5d6 in lookup_symbol_aux_psymtabs (block_index=0,
name=0x7fffab13ade0 "getenv::graph", linkage_name=0x0,
domain=VAR_DOMAIN) at symtab.c:1607
#3  0x00000000005c2df1 in lookup_symbol_file (name=0x7fffab13ade0
"getenv::graph", linkage_name=0x0, block=0x296e67f0,
domain=VAR_DOMAIN, anonymous_namespace=0) at cp-namespace.c:504
#4  0x00000000005c301f in cp_lookup_symbol_in_namespace
(namespace=0xe3f1cd0 "getenv", name=0x2b086410 "graph",
linkage_name=0x0, block=0x296e67f0, domain=VAR_DOMAIN) at
cp-namespace.c:278
#5  0x00000000005c310b in cp_lookup_symbol_imports (scope=0x29eda318
"pir::PathBalanceChecker::visit(pir::BlockComp&)", name=0x7fffab13ade0
"getenv::graph", linkage_name=0x24 <Address 0x24 out of bounds>,
block=0x1, domain=VAR_DOMAIN, search_parents=45746864) at
cp-namespace.c:325
#6  0x00000000005c32bd in cp_lookup_symbol_imports (scope=0x1706a5c0
"std", name=0x2b086410 "graph", linkage_name=0x0, block=0x296e67f0,
domain=VAR_DOMAIN, search_parents=0) at cp-namespace.c:370
#7  0x00000000005c32bd in cp_lookup_symbol_imports (scope=0x2966da80
"SubsystemBlock", name=0x2b086410 "graph", linkage_name=0x0,
block=0x296e67f0, domain=VAR_DOMAIN, search_parents=1) at
cp-namespace.c:370
#8  0x00000000005c3320 in cp_lookup_symbol_namespace (scope=0x2966da80
"SubsystemBlock", name=0x2b086410 "graph", linkage_name=0x0,
block=0x296e67f0, domain=VAR_DOMAIN, search_parents=1) at
cp-namespace.c:405
#9  0x000000000050d9fd in lookup_symbol_aux (name=<value optimized
out>, block=0x2966d760, domain=VAR_DOMAIN, lang=language_cplus,
is_a_field_of_this=0x7fffab13b06c) at symtab.c:1406
----------------- %< ---------------------------

The strange thing about this stack is that the object "s" is of time
SubsystemBlock and the graph field is a direct sub-field of that
structure. However, gdb seems to be doing all sorts of lookups in
various unrelated namespaces: for example in
pir::PathBalanceChecker::visit etc. I don't know why gdb would be
looking at that symbol at all when attempting to print "s->graph".

Is this a known issue? I could provide more information if someone
could tell me what.

Regards,
Srinath

[1] http://stackoverflow.com/questions/375913/what-can-i-use-to-profile-c-code-in-linux

Re: Massive slowdown printing values in gdb-7.1

[Joel Brobecker]

> I have been testing gdb 7.1 lately and have noticed that under some
> circumstances (which I have been unable to reproduce with a simple
> program), it is taking extremely long (~ 30 seconds) to print a simple
> expreession such as

I don't know if this might help, but have you tried gdb-7.2 and
the CVS HEAD? gdb-7.2 and a daily snapshot of the development branch
are both available at ftp://sourceware.org/pub/gdb/.

-- 
Joel

Re: Massive slowdown printing values in gdb-7.1

[Srinath Avadhanula]

Hi Joel,

Thanks for the answer.

On Mon, Sep 6, 2010 at 7:31 PM, Joel Brobecker <brobecker@adacore.com> wrote:
>
> I don't know if this might help, but have you tried gdb-7.2 and
> the CVS HEAD? gdb-7.2 and a daily snapshot of the development branch
> are both available at ftp://sourceware.org/pub/gdb/.
>

That did it! :) The latest from CVS: GNU gdb (GDB) 7.2.50.20100906
doesn't have this problem anymore.

Thanks a bunch :)

Srinath

Re: Massive slowdown printing values in gdb-7.1

[Joel Brobecker]

> That did it! :) The latest from CVS: GNU gdb (GDB) 7.2.50.20100906
> doesn't have this problem anymore.

Wonderful news. If it's not asking too much, it would be interesting
to determine whether 7.2 still shows the issue or not...

-- 
Joel

Re: Massive slowdown printing values in gdb-7.1

[Srinath Avadhanula]

On Mon, Sep 6, 2010 at 9:35 PM, Joel Brobecker <brobecker@adacore.com> wrote:
>> That did it! :) The latest from CVS: GNU gdb (GDB) 7.2.50.20100906
>> doesn't have this problem anymore.
>
> Wonderful news. If it's not asking too much, it would be interesting
> to determine whether 7.2 still shows the issue or not...
>

I tried out gdb 7.2 from

http://ftp.gnu.org/gnu/gdb/gdb-7.2.tar.bz2

and that didn't have the problem as well :)

Thanks,
Srinath

Re: Massive slowdown printing values in gdb-7.1

[Tom Tromey]

>>>>> "Joel" == Joel Brobecker <brobecker@adacore.com> writes:

>> That did it! :) The latest from CVS: GNU gdb (GDB) 7.2.50.20100906
>> doesn't have this problem anymore.

Joel> Wonderful news. If it's not asking too much, it would be interesting
Joel> to determine whether 7.2 still shows the issue or not...

This is probably the namespace-related performance bug.
It was fixed in CVS a while ago.  I can dig up the PR if you need it.

Tom