I confirm the bug on my system too. Exactly as described by Darrell.

Tagging as a regression and adding to the R14 etherpad road map. The problem does not exist on 3.5.10 or 3.5.13.0. I don't think the bug exists in 3.5.13.2, but I only have a Live CD to test and the menu appears almost as fast as the disk gets accessed.

Did the Qt3/TQt3 patches committed in Bug 1703 make any difference?

>Did the Qt3/TQt3 patches committed in Bug 1703 make any difference?
No difference here.

On my dual core systems, the menu does not appear for about 6 to 7 seconds.

I keep panel applet handles enabled all the time. About three seconds after pressing Alt+F1 an applet handler pointer appears in the menu icon.

The menu appears immediately when using the mouse.

I did check 3.5.13.2 and the menu appears immediately with Alt+F1.

(In reply to comment #4)
> >Did the Qt3/TQt3 patches committed in Bug 1703 make any difference?
> No difference here.
> 
> On my dual core systems, the menu does not appear for about 6 to 7 seconds.
> 
> I keep panel applet handles enabled all the time. About three seconds after
> pressing Alt+F1 an applet handler pointer appears in the menu icon.
> 
> The menu appears immediately when using the mouse.
> 
> I did check 3.5.13.2 and the menu appears immediately with Alt+F1.

OK, good to know.  Was your CPU usage high while waiting for the menu to show up?

Yes, CPU usage ramps high until the menu appears: kicker.

I bisected backup package sets and narrowed the problem to between May 17 and May 19. With that narrow window I suspect the cause is commit 718f6ae3, 2013-05-19, "Add tooltip support in KMenu."

I am building a tdebase package with the patch reversed and will report.

Reversing commit 718f6ae3 made no difference. Yet I see a difference between my package set of approximately May 16 and of May 19. That commit might mask a related problem.

When I change to the kickoff menu, flush the Trinity cache and restart Trinity, Alt+F1 opens the kickoff menu immediately. Toggling to the classic menu and repeating the process, Alt+F1 fails to open the menu immediately.

In the panel configuration Menus dialog, there is an option named Open menu on mouse hover. The option applies only to the kickoff menu and is disabled/ghosted when using the classic menu.

Switching to the kickoff menu enables that dialog option. Oddly, unchecking the option has no effect. Reopen the dialog and the check box is always checked. Further, I can wait all day with the mouse pointer hovered over the menu button and the kickoff menu never opens.

I suspect that broken check box bug is related to the Alt+F1 bug.

Another question is why should the "Open menu on mouse hover" check box be disabled for the classic menu? Seems like a useful feature for either menu.

I think I see the problem.

In menutab_impl.cpp, kickerrc config file reads are made:

[General]
LegacyKMenu
OpenOnHover

No LegacyKMenu key exists in my kickerrc [General] section.

In another section the same reads are made:

[buttons]
LegacyKMenu
OpenOnHover

The writeEntry for each is made to the [buttons] group.

All quite weird.

There is another kickerrc group option name KMenu. That is where both the LegacyKMenu and OpenOnHover option should be stored and read/written.

I will try to create a patch, but I might need help. Let's see how this goes.... :-)

Created attachment 1684 [details]
Preliminary patch to fix Menus dialog

I have the kickerrc keys all in the correct [KMenu] location. For testing I toggled the associated check boxes and verified the kickerrc file updated correctly.

Stil remaining:

* Alt+F1 works immediately with the kickoff menu but not the classic menu.

* In the Menus dialog, selecting the Apply button closes the entire dialog. This does not happen in the other panel config dialogs.

* "Open menu on mouse hover" does not work for either menu.

Any configuration action that resets the panel causes the Alt+F1 shortcut to always require several seconds to open the classic menu. The kickoff menu is not affected.

> * In the Menus dialog, selecting the Apply button closes the entire dialog.
> This does not happen in the other panel config dialogs.

I also noticed this behavior. Not sure if this is a bug or if it is intentional since I haven't look at any code yet.

As for the Alt+F1 bug, it takes about 9 or 10 seconds on my computer to open.

Running Kicker under gdb, then breaking into the process (Ctrl+C) and generating a backtrace (bt) during the anomalously high CPU load might help pinpoint the malfunctioning code.

Do the commits between May 16 and May 19 provide clues? My package set from May 16 has no problems with Alt+F1 and my package set from May 19 (and onward) does.

>Running Kicker under gdb
What are the steps to do that?

I ran gdb --args kicker, then pressed r, and gdb responded

ERROR: kicker is already running

(Odpověď na komentář #14)
> >Running Kicker under gdb
> What are the steps to do that?
> 
> I ran gdb --args kicker, then pressed r, and gdb responded
> 
> ERROR: kicker is already running

You can try attach to already running kicker:

gdb --pid $(pgrep kicker)

>gdb --pid $(pgrep kicker)
Thanks, but then do what next?

I will look into this bug, even though before Thursday I may not have much free time

Created attachment 1723 [details]
kicker patch for main menu delay

This is more a workaround than a patch, but if it works for you as well I would suggest we should consider using it. Please test, if possible also on older hardware.

The delay when displaying the main menu using Alt+F1 the first time is caused by two calls to tqApp->processEvents(). Each of these calls runs for exactly 3 seconds, so the total time needed to display the menu is about 6 seconds.
I am not sure what kicker is doing during those 6 seconds, obviously it must be doing something otherwise the call to processEvents() would return earlier, as it happens when Alt+F1 is used after the first time.
Strangely, when using the Kickoff menu, the same code does not display such delay in both calls.

The proposed patch as said is a workaround, in that it does not fix the root cause of the problem but simply put a time limit (10ms) to each of the two processEvents() calls. On my system (i5, one year old) it is more than enough to make the main panel appear and then display the main menu.

The patch from Darrell for the kickerrc file still applies, even though it is not strictly necessary for the workaround to actually work.

> Another question is why should the "Open menu on mouse hover" check box be
> disabled for the classic menu? Seems like a useful feature for either menu.

I opened bug 1767 for this.

Michele, thank you for looking into this. I have not yet tested the patch, but I have questions.

* What changed from 3.5.13.2? I am unable to replicate the bug in 3.5.13.2.

* Why is there a delay with only the first time Alt+F1 is used? I am unable to replicate the bug in 3.5.10 as well, which implies throughout the history of Alt+F1, there was not a problem. The bug was introduced (or unmasked) in R14.

* Why is there no delay with the kickoff menu?

* Why is there no delay with the mouse pointer?

As you defined the patch as a work-around, I would like to see us trace what happened in R14 to introduce or unmask the delay. I have been walking through the patch history to menumanager.cpp and panelbutton.cpp sources:

http://git.trinitydesktop.org/cgit/tdebase/log/kicker/kicker/core/menumanager.cpp
http://git.trinitydesktop.org/cgit/tdebase/log/kicker/libkicker/panelbutton.cpp

I am not noticing anything obvious. That implies the change is deeper, but I'm not a C++ hacker to know where to to begin looking.

In comment 6 I shared how I used older package sets to determine the bug was introduced between May 17 and May 19. Initially I suspected commit 718f6ae3, which added tooltip support to the menu. Yet reversing that code did not eliminate the delay. There is no doubt at my end the menu delay bug occurs between my package sets between May 17 and May 19. I would like to see us find a clue in that period of commits.

I'm not saying your solution is incorrect --- we have throughout the Trinity project discovered flaws in original KDE3 code that remained latent until tweaks in Trinity unmasked or forced the bugs to surface. Such could be the case here. Perhaps this menu delay was always present but latent or not forceable until changes in Trinity infrastructure revealed the delay. R14 introduced a lot of infrastructure changes.

I'd be more comfortable if a proposed patch answered all of the above questions. :-)

I tested the patch on four systems. Two are dual core systems. The others are a PI and PII --- about as slow as can be tested nowadays.

On the two dual core systems, the delay was ever-so-slightly noticeable. Possibly because I was looking for a delay.

On the PI and PII, first I tested without the patch. The delay was about 18 to 19 seconds. Second usage of Alt+F1 was about 3.5 to 4 seconds for the menu to appear. With the patch the initial delay was about 4.7 seconds. Second usage was about 1.5 seconds.

> On the PI and PII, first I tested without the patch. The delay was about 18 to
> 19 seconds. Second usage of Alt+F1 was about 3.5 to 4 seconds for the menu to
> appear. With the patch the initial delay was about 4.7 seconds. Second usage
> was about 1.5 seconds.

I think those 3.5 or 4 seconds are needed on PI and PII to handle the graphics. In the TDE code there is a comment that says that the menu can take an unknown time to appears/disappear, depending on the hardware used.
The additional time required without the workaround is caused by the call to processEvent, as explained.

I offered no comments about the patched times on the PI and PII. Just reporting test results. :-)

I still think we need to resolve what patch(es) between May 17 and May 19 either caused the bug or unmasked what had been a long-time latent bug --- and how that coincides with the proposed patch.

Hi Darrell,
I agree with you that if we could find the root cause of the problem it would
be better. That's why I clearly mentioned the patch is a workaround (and I am
not a fun of workarounds at all).

> * Why is there a delay with only the first time Alt+F1 is used? I am unable to
> replicate the bug in 3.5.10 as well, which implies throughout the history of
> Alt+F1, there was not a problem. The bug was introduced (or unmasked) in R14.
Still don't know. What I can say so far is that after (re)starting kicker, it
has some backlog of events to handle and this is causing the delay in
processEvent().

> * Why is there no delay with the kickoff menu?
Still don't know either. But the kickoff menu is a different class, so it does
different things.

> * Why is there no delay with the mouse pointer?
Part of the code used when pressing Alt+F1 is not used when using the mouse.
Mainly because using the mouse the menu button is visible for sure (otherwise
you couldn;t click on it), so the call to processEvent() to make sure the
button is visible is not needed.

>I have been walking through the patch history to menumanager.cpp and >panelbutton.cpp sources:
The delay could be caused by a different part of kicker, not necessary by the
menumanager. By the way, the first part of the code executed when pressing
Alt+F1 is the same for both kickoff and TDE classic menu style.

> I'd be more comfortable if a proposed patch answered all of the above
> questions. :-)
Me too :)

The one clue we have at the moment is May 17 to May 19. Or to have a safe buffer, May 16 to May 20. Not that many patches in that period: 29.

I'm comfortable with the idea that one or more of those patches from that period unmasked a latent bug rather than introduced. As I mentioned, we've seen that happen before.

(In reply to comment #25)
> The one clue we have at the moment is May 17 to May 19. Or to have a safe
> buffer, May 16 to May 20. Not that many patches in that period: 29.
> 
> I'm comfortable with the idea that one or more of those patches from that
> period unmasked a latent bug rather than introduced. As I mentioned, we've seen
> that happen before.

Another clue is the fact that Kickoff and TDE Classic menus do different things and have different behavior. I will look more into it when I have time.

Created attachment 1724 [details]
new patch

This time this is a proper patch :)
The problem was a race condition between a timer being triggered and being served.

The PanelKMenu::initialize() function (which is called when Alt+F1 is pressed) starts a timer for monitoring when the menu button is displayed. The timer is started with interval ==0 and to be continuously triggered.

displayRepairTimer->start(0, FALSE);

When the timer routine (PanelKMenu::repairDisplay) is served, if the menu button is visible the timer is stopped.
The race condition was generated by the fact the the timer routine was invoked continuously, but the application didn't have enough time to verify whether the button was visible or not because it was too busy serving the timer routine calls. Tests that I have done showed that the timer was triggered more that 500000 times on my machine.

The fix as usual is very simple. By triggering the timer routine every 5ms, we give time to the application to verify if the button is visible without overloading it with thousands of calls.

Darrell, please test on PI and PII. If it works fine there, good. If you find it too slow compared to 3.5.10, we can consider increasing the time interval.

The first patch from Darrell still applies too.

To answer these questions:

> * What changed from 3.5.13.2? I am unable to replicate the bug in 3.5.13.2.
Still to be investigated

> * Why is there a delay with only the first time Alt+F1 is used? I am unable to
> replicate the bug in 3.5.10 as well, which implies throughout the history of
> Alt+F1, there was not a problem. The bug was introduced (or unmasked) in R14.
See comment 27

> * Why is there no delay with the kickoff menu?
Kickoff menu does not use the displayRepairTimer. Only TDE Classic menu uses that.
> 
> * Why is there no delay with the mouse pointer?
Different invocation code, no display timer because the button is visible for sure

> I'm not saying your solution is incorrect --- we have throughout the Trinity
> project discovered flaws in original KDE3 code that remained latent until
> tweaks in Trinity unmasked or forced the bugs to surface. Such could be the
> case here. Perhaps this menu delay was always present but latent or not
> forceable until changes in Trinity infrastructure revealed the delay. R14
> introduced a lot of infrastructure changes.
My guess at the moment is that with the changes in thread management in R14 (of which I am not quite familiar with but Tim for sure is) we have exposed such race condition that before didn't happen. Maybe everything was invoked in the same thread before and the timer routine was triggered before the timer could be triggered again.

On May 14, commit 4eba9b82 was pushed.
Description is "[qt3] Fix a number of threading data races. Add proper thread termination handler. This partially resolves Bug 1508".

Darrell, any chance you can trying reverting this commit and see if it makes any difference on your system compare to the packages of May 16 and May 19? I am guessing that maybe the sources of the package of May 16 were not updated to the last changes of the time

And equivalent commit 9a4765a6 for TQt3, same time

>please test on PI and PII.
Okay. Please be aware that anything I do with these old machines takes a long time. They are great machines for stress testing things like this, but are a bugger to work with because they are so slow.

>any chance you can trying reverting this commit
Yes, I can test. If the problem is caused by a race condition then would be nice to discover that particular commit unmasked a long time latent bug. Could well be my May 16 package set was built without fully updating my source tree after that patch was pushed to git May 14. Normally I update my source tree before building a new package set, but I can't say with certainty I always did that. :-)

>any chance you can trying reverting this commit
Looks like too many changes to those sources since the original commit. A simple --reverse of the patch doesn't succeed. Way beyond me how to massage the original patch to test whether that was the commit that unmasked the bug.

With the latest patch, with populated tdesycoca caches, classic menu search bar disabled, and restarting Trinity for each test (rather than restarting kicker):

On my dual core systems the classic menu appears immediately. On one of the systems, there is an ever-so-slight delay of the classic menu appearing the first time compared to the kickoff menu. Ever-so-slight --- on the dual core systems I can't measure the difference in any meaningful way. Likely not noticeable to somebody not testing this bug report. :-)

On the PI the classic menu delay the first time is about 6.5 seconds. The kickoff menu appears the first time in about 4.5 to 5.5 seconds. With the mouse the menu appears the first time in about 5.5 seconds.

On the PII the classic menu delay the first time is about 3 to 4 seconds. The kickoff menu appears the first time in about 2 to 2.5 seconds. With the mouse the menu appears the first time in about 3.5 seconds.

Notes: The PI has a slight advantage with a 400 MHz K6-III+ versus a 350 MHz PII. The PII has slight advantage from a first generation AGP video card capable of basic DRI rendering and 448MB of RAM versus 256MB for the PI.

Hi Darrell, 
thanks for testing on such old hardware. Appreciate your effort especially considering the long time required.

> On my dual core systems the classic menu appears immediately.
> On the PI the classic menu delay the first time is about 6.5 seconds. The
> kickoff menu appears the first time in about 4.5 to 5.5 seconds. With the mouse
> the menu appears the first time in about 5.5 seconds.
> On the PII the classic menu delay the first time is about 3 to 4 seconds. The
> kickoff menu appears the first time in about 2 to 2.5 seconds. With the mouse
> the menu appears the first time in about 3.5 seconds.

It looks like the patch is doing its job so :)
Kickoff and TDE classic menus are different objects, so there is no requirement for the time to be exactly the same. As long as the times are similar I think it is ok.
Same for when using the mouse: as already said, using the mouse executes less code compared to using Alt+F1. The structure is something like this:

entry point for Alt+F1
....
code
....
entry point for mouse

so that 0.5-1 second delay is the time used in the first part.
Before the race condition was making the first part very long to execute due to the extremely high number of times the timer was triggered.

Thanks for your help. As for reverting the suggested commit, if it is not easy to do then don't bother doing it. That commit is very important and definitely something that will not be reverted. My request was more for trying to understand if such commit highlighted this (and perhaps other) race condition that before didn't happen.

>thanks for testing on such old hardware. Appreciate your effort especially
>considering the long time required.
Thanks. The old hardware is a nuisance to work with but they nicely reveal problems not easily noticed on modern multi-core systems. Most of the time they sit powered down but when needed I use them for these test cases.

>It looks like the patch is doing its job so
No complaints here. :-)

>My request was more for trying to understand if such commit highlighted
>this (and perhaps other) race condition that before didn't happen.
Yes, I understood your intention. Unfortunately there have been additional patches to the sources that renders reversing that original commit difficult. I also tried installing my last known package set where Alt+F1 functioned correctly, verified that function, then installed the next package set where Alt+F1 was broken. I then tried to rebuild tdebase with just your Alt+F1 patch. I was unsuccessful. Too many renaming changes in TQt3 and tdelibs since that old date. That is, I would not have been able to create the same package set. I don't store or backup tarball snapshots, although once in a blue moon, like this example, I wish I did.

I'm content the commit you identified was the beginning of when Alt+F1 began misfunctioning. Your patch revealed the bug was always there, just latent, and only when threading issues were corrected did the bug appear. I suspect the same thing is happening in bug 1172.

Created attachment 1725 [details]
Fix saving kicker settings in wrong section

I looked at the patch from attachment 1684 [details]
and I see there several problems:

1) Along to tdebase/kicker/libkicker/kickerSettings.kcfg Kicker expect settings LegacyKMenu and OpenOnHover in the General section. Moving LegacyKMenu to section KMenu would disrupt users previous settings.

2) I looked into the Kicker code and found the setting OpenOnHover is used only in class KNewButton - only in the KickOff menu. I think it only affects the switching menu tabs in KickOff menu. It does not serve to open the menu itself. Enabling this setting for the classic menu therefore is not useful.

The attached patch only moves saving settings to the correct section.

>Moving LegacyKMenu to section KMenu would disrupt users previous settings.
True, but that is the common sense location. :-) That is partly how I got confused with this bug when I studied the config file.

>It does not serve to open the menu itself.
Okay, makes sense.

Fixed in GIT hash 0230e386 and 6523942e.