Upgrade endeavours - the third day

[Peter <pmc@citylink.dinoex.sub.org>]

On the third day, that is, yesterday, things kept nagging me. So
I decided to go for the boring endeavour of reading the source.

I had tried debugging the day before: while the program ventures to
open the menu, kill it so that it writes a core. Some internal
function then happens to write a backtrace in the console, and I can
read another one out of the corefile. Both are entirely disparate, and
neither is much helpful.
I cannot easily do live-debugging, because, as mentioned before, the
X is mostly blocked during the interesting phase. I tried to move the
DISPLAY to another X, but somehow this also didn't work well.

So I resorted to the tedious old-fashioned way of inserting printf()
into the code, and that got me to something: the stall happens in
function set_frame_menubar(). That function gets invoked from
x_menu_bar_open_internal() when hitting <f10>, and from whoknowswhere
when clicking.

I ventured on from there, into

xmenu.c:set_frame_menubar() line 1036:
    (in a loop repeated) call to parse_single_submenu()
menu.c:parse_single_submenu() line 555:
    call to single_keymap_panes()
menu.c:single_keymap_panes() line 290:
    call to map_keymap_canonical()
keymap.c:map_keymap_canonical() line 615:
    call to map_keymap_internal()
keymap.c:map_keymap_internal() line 565:
    (in a loop repeated) call to map_keymap_item()
keymap.c:map_keymap_item() line 508:
    indirect call (from menu.c:single_keymap_panes() line 290, param 2)
    to single_menu_item()
menu.c:single_menu_item() line 430:
    call to single_keymap_panes() -> Ups! We've been there already!

Apparently this runs some elaborate indirect and recursive code, 
and there are too many functions invoked to notice with the bare eye
where it delays. I also noticed that this code is run a couple of
times, and it is also run before the X window gets created - and
then it can be fast!
So, putting some profiling into the code was necessary to get further.
And then there were some results:

  µs			desktop		laptop
startup			   633'359       2'179'629
menu open		 1'621'489	   254'082
menu close		 1'486'825	   256'875

with TRUSS		desktop		laptop
startup			 1'527'100	 3'256'595
menu open		45'586'904      11'912'108
menu close		46'331'740	11'140'115

Tracking it down: accumulated time spent in parse_menu_item():

  µs			desktop		laptop
startup			   194'042         103'867
menu open		 1'292'654	   117'530
menu close		 1'203'057	    91'463

Such a difference is in no way explainable with CPU differences.

That was about the third day, that is, around 6 AM today.