Re: [tree-ssa mudflap] slow startup - gotcha!

[Eyal Lebedinsky <eyal at eyal dot emu dot id dot au>]

Eyal Lebedinsky wrote:
> 
> Eyal Lebedinsky wrote:
> >
> > Since the changes early this month Everything is very slow. I now
> > checked and I see that the whole slowdown in before my main() is
> > entered. It seems that everything is registered up-front when the
> > DLLs are opened.
> 
> Following up on my own post, looking at a trace of my simple
> program with the old and then the new compiler, I see that there
> is a significant increase of 'string literal's registered.

Now that I have spent a long time watching a process take 30m to
start, I starting taking gdb snapshots and I think I can see
what is going on.

I see the binary tree severly lopsided, or else the searches are
badly done. Here is the bottom of one such backtrace:
===================================
#16759 0x4182ac32 in __mf_find_objects_rec (low=1078247093,
high=1078247121,
    nodep=0x8204f4c, objs=0xbffff074, max_objs=1)
    at ../../../gcc/libmudflap/mf-runtime.c:1545
        count = 0
        node = (__mf_object_tree_t *) 0x8204f58
        r_l = (__mf_object_tree_t *) 0x0
        l_r = (__mf_object_tree_t *) 0x0
#16760 0x4182ac32 in __mf_find_objects_rec (low=1078247093,
high=1078247121,
    nodep=0x8204ef4, objs=0xbffff074, max_objs=1)
    at ../../../gcc/libmudflap/mf-runtime.c:1545
        count = 0
        node = (__mf_object_tree_t *) 0x8204f00
        r_l = (__mf_object_tree_t *) 0x0
        l_r = (__mf_object_tree_t *) 0x0
#16761 0x4182ac32 in __mf_find_objects_rec (low=1078247093,
high=1078247121,
    nodep=0x8204e44, objs=0xbffff074, max_objs=1)
    at ../../../gcc/libmudflap/mf-runtime.c:1545
        count = 0
        node = (__mf_object_tree_t *) 0x8204ea8
        r_l = (__mf_object_tree_t *) 0x0
        l_r = (__mf_object_tree_t *) 0x0
#16762 0x4182ac32 in __mf_find_objects_rec (low=1078247093,
high=1078247121,
    nodep=0x8204dec, objs=0xbffff074, max_objs=1)
    at ../../../gcc/libmudflap/mf-runtime.c:1545
        count = 0
        node = (__mf_object_tree_t *) 0x8204df8
        r_l = (__mf_object_tree_t *) 0x0
        l_r = (__mf_object_tree_t *) 0x0
#16763 0x4182ac32 in __mf_find_objects_rec (low=1078247093,
high=1078247121,
    nodep=0x8204d40, objs=0xbffff074, max_objs=1)
    at ../../../gcc/libmudflap/mf-runtime.c:1545
        count = 0
        node = (__mf_object_tree_t *) 0x8204da0
        r_l = (__mf_object_tree_t *) 0x0
        l_r = (__mf_object_tree_t *) 0x0
#16764 0x4182aca3 in __mf_find_objects_rec (low=1078247093,
high=1078247121,
    nodep=0x8204c90, objs=0xbffff074, max_objs=1)
    at ../../../gcc/libmudflap/mf-runtime.c:1573
        count = 0
        node = (__mf_object_tree_t *) 0x8204cf0
        r_l = (__mf_object_tree_t *) 0x0
        l_r = (__mf_object_tree_t *) 0x0
#16765 0x4182aca3 in __mf_find_objects_rec (low=1078247093,
high=1078247121,
    nodep=0x418407ac, objs=0xbffff074, max_objs=1)
    at ../../../gcc/libmudflap/mf-runtime.c:1573
        count = 0
        node = (__mf_object_tree_t *) 0x8204c40
        r_l = (__mf_object_tree_t *) 0x0
        l_r = (__mf_object_tree_t *) 0x0
#16766 0x4182adf9 in __mf_find_objects (ptr_low=0, ptr_high=0, objs=0x0,
    max_objs=0) at ../../../gcc/libmudflap/mf-runtime.c:1617
No locals.
#16767 0x41829b05 in __mfu_register (ptr=0x4044beb5, sz=29, type=4,
    name=0x40451945 "string literal")
    at ../../../gcc/libmudflap/mf-runtime.c:1035
        ovr_objs = {0x85d91e8}
        num_overlapping_objs = 1073821264
#16768 0x418298ba in __mf_register (ptr=0x0, sz=0, type=0, name=0x0)
    at ../../../gcc/libmudflap/mf-runtime.c:982
        rc = 0
        rc = 0
#16769 0x403483d4 in _GLOBAL__I_sm0v13_mudflap () at klmgr.c:4580
No locals.
#16770 0x4042dbea in smv001 () from
/ssa/builds/20030627-mfi/bin/libssace.so
No symbol table info available.
#16771 0x401425be in scx004 () from
/ssa/builds/20030627-mfi/bin/libssace.so
No symbol table info available.
#16772 0x40009cc7 in call_init () from /lib/ld-linux.so.2
No symbol table info available.
#16773 0x40009e1d in _dl_init () from /lib/ld-linux.so.2
No symbol table info available.
===================================

Note the stack depth (16773). At this point we are very close to
the end of this process (the program CPU usage soon dropped from
the high 90s to idle as the server was waiting for clients).

The rest of the stack is a repeated entry for 'mf-runtime.c:1545'
with a different 'node=' address each time. The code here is"

	  /* Traverse down left subtree. */
	  count = 0;
	  if (low < node->data.low)
1545:	    count += __mf_find_objects_rec (low, min(high,
node->data.low),
	                                    & node->left, objs, max_objs);


It seems that we are constantly "Traverse down left subtree"ing
as the comment says.

This is not my strong area. It seems that the tree is rebalanced
based on an ageing rule? At program startup everything has the same
age (I think) so the tree should be balanced based on its depth
at this stage (i.e. minimize depth).

Are we registering all the static objects in monotonic address due
to the way we parse the symbol table? This is often a worse-case
for tree building.

[I keep telling myself that the weather is bad, cold, raining and
dark, and there is no way I could have seen those orchids on Black
Mtn that were mentioned on the local list this weekend...]

--
Eyal Lebedinsky (eyal@eyal.emu.id.au) <http://samba.org/eyal/>