533470 - delay (>4s) on presenting any menu

Status: RESOLVED FIXED

(Firefox :: Menus, defect)

Description

[jez]

User-Agent:       Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.2b4) Gecko/20091207 Gentoo Firefox/3.6b4
Build Identifier: Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.2b4) Gecko/20091207 Gentoo Firefox/3.6b4

There is a delay of a few seconds between clicking on a menu item, right-clicking for a context menu, or hovering over a submenu item and that menu or submenu being displayed. There is also a similar length delay between clicking on a menu item and that action being executed. This only effects the 3.6 beta.

Other than this, performance is perfectly snappy, including swithcing between and creating new tabs etc.

(running gentoo linux, compiled using portage and gcc 4.4.2, glibc 2.9).

Reproducible: Always

Steps to Reproduce:
1.click for any menu
2.
3.
Actual Results:  
a > 4 second delay on a E2180 processor.

Expected Results:  
no delay

using theme "full flat 3.5". haven't tried other themes...

Comment 1

[jez]

same problem using default theme.

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

jez, would you have time to test former versions of beta versions of Firefox 3.6 to check when it appeared the first time? further which extensions do you have installed? You should try to run Firefox in Safe Mode (http://support.mozilla.com/kb/Safe+Mode)

Comment 3

[jez]

I had the problem in beta 3, don't think it happened in beta 2 but I should confirm this.

Problem exists in safe mode, and when a menu is requested, "socket(): Address family not supported by protocol" is printed in the terminal. I should note that all input is suspended during the delay, and if I move the window around it is not repainted.

Comment 4

[jez]

This is interesting. After running firefox under strace, the problem has disappeared. Now running firefox out of safe mode and without strace, and no delays on the menus.

Could it be a prelink issue? I'm re-running "prelink -amR" to see if that brings it back.

Comment 5

[jez]

After a few days of working OK, I booted up this morning and the problem reappeared.

I think I can see the problem, it seems it's not being able to find pulseaudio. Once I made sure that the pulse daemon was running, menus displayed quickly again.

Here's some strace monitoring a slow menu render:

poll([{fd=76, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=76, revents=POLLOUT}])
writev(76, [{"\20\0\5\0\n\0\0\0PULSE_SINK\0\0"..., 20}, {NULL, 0}, {""..., 0}], 3) = 20
poll([{fd=76, events=POLLIN}], 1, -1)   = 1 ([{fd=76, revents=POLLIN}])
read(76, "\1\0\t\0\0\0\0\0\24\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 32
read(76, 0x7f494b0cb074, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=76, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=76, revents=POLLOUT}])
writev(76, [{"\24\0\6\0\7\1\0\0\24\2\0\0\37\0\0\0\0\0\0\0\0\1\0\0"..., 24}, {NULL, 0}, {""..., 0}], 3) = 24
poll([{fd=76, events=POLLIN}], 1, -1)   = 1 ([{fd=76, revents=POLLIN}])
read(76, "\1\0\n\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 32
read(76, 0x7f494b0cb074, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=76, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=76, revents=POLLOUT}])
writev(76, [{"\20\0\5\0\f\0\0\0PULSE_SOURCE"..., 20}, {NULL, 0}, {""..., 0}], 3) = 20
poll([{fd=76, events=POLLIN}], 1, -1)   = 1 ([{fd=76, revents=POLLIN}])
read(76, "\1\0\v\0\0\0\0\0\25\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 32
read(76, 0x7f494b0cb074, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=76, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=76, revents=POLLOUT}])
writev(76, [{"\24\0\6\0\7\1\0\0\25\2\0\0\37\0\0\0\0\0\0\0\0\1\0\0"..., 24}, {NULL, 0}, {""..., 0}], 3) = 24
poll([{fd=76, events=POLLIN}], 1, -1)   = 1 ([{fd=76, revents=POLLIN}])
read(76, "\1\0\f\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 32
read(76, 0x7f494b0cb074, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=76, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=76, revents=POLLOUT}])
writev(76, [{"\20\0\5\0\f\0\0\0PULSE_COOKIE"..., 20}, {NULL, 0}, {""..., 0}], 3) = 20
poll([{fd=76, events=POLLIN}], 1, -1)   = 1 ([{fd=76, revents=POLLIN}])
read(76, "\1\0\r\0\0\0\0\0\26\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 32
read(76, 0x7f494b0cb074, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=76, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=76, revents=POLLOUT}])
writev(76, [{"\24\0\6\0\7\1\0\0\26\2\0\0\37\0\0\0\0\0\0\0\0\1\0\0"..., 24}, {NULL, 0}, {""..., 0}], 3) = 24
poll([{fd=76, events=POLLIN}], 1, -1)   = 1 ([{fd=76, revents=POLLIN}])
read(76, "\1\0\16\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 32
read(76, 0x7f494b0cb074, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=76, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=76, revents=POLLOUT}])
writev(76, [{"<\0\2\0\0\0\300\1+\2\1\0"..., 12}, {NULL, 0}, {""..., 0}], 3) = 12
poll([{fd=76, events=POLLIN}], 1, -1)   = 1 ([{fd=76, revents=POLLIN}])
read(76, "\1\1\20\0\0\0\0\0\236] \1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 32
read(76, 0x7f494b0cb074, 4096)          = -1 EAGAIN (Resource temporarily unavailable)
close(76)                               = 0
open("/dev/shm/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 76
fstat(76, {st_mode=S_IFDIR|S_ISVTX|0777, st_size=60, ...}) = 0
getdents(76, Segmentation fault

strace segfaulted, firefox continued.

Comment 6

[jez]

Here's a backtrace:

#0  0x00007f9b3f1847d1 in *__GI___nptl_create_event () at events.c:27
#1  0x00007f9b3f185c34 in __pthread_create_2_1 (
    newthread=<value optimized out>, attr=<value optimized out>, 
    start_routine=<value optimized out>, arg=<value optimized out>)
    at ../nptl/sysdeps/pthread/createthread.c:224
#2  0x00007f9b1f8ad532 in asyncns_new (n_proc=1) at asyncns.c:549
#3  0x00007f9b207636c1 in pa_socket_client_new_string (m=0x7f9b2213be58, 
    use_rtclock=true, name=<value optimized out>, 
    default_port=<value optimized out>) at pulsecore/socket-client.c:480
#4  0x00007f9b20993a6a in try_next_connection (c=0x7f9b27635ce0)
    at pulse/context.c:868
#5  0x00007f9b209949de in pa_context_connect (c=0x7f9b27635ce0, 
    server=0x7f9b3e3694da "", flags=PA_CONTEXT_NOFLAGS, api=0x0)
    at pulse/context.c:1024
#6  0x00007f9b20bc9cc4 in context_connect (c=0x7f9b223fbfc0, nofail=0)
    at pulse.c:232
#7  0x00007f9b20bc9ece in pulse_driver_open (c=0x7f9b223fbfc0) at pulse.c:372
#8  0x00007f9b218fc1b0 in driver_open (c=0x7f9b223fbfc0) at dso.c:271
#9  0x00007f9b218f4898 in context_open_unlocked (c=0x7f9b223fbfc0)
    at common.c:291
#10 0x00007f9b218f50c5 in ca_context_play_full (c=0x7f9b223fbfc0, id=0, 
    p=0x7f9b2714dad0, cb=0, userdata=0x0) at common.c:515
#11 0x00007f9b218f5470 in ca_context_play (c=0x7f9b223fbfc0, id=0)
    at common.c:460
#12 0x00007f9b3d4e5f2b in nsSound::PlayEventSound (this=<value optimized out>, 
    aEventId=6) at nsSound.cpp:501
#13 0x00007f9b3cfcbfe4 in nsMenuPopupFrame::ShowPopup (this=0x7f9b278a0520, 
    aIsContextMenu=<value optimized out>, aSelectFirstItem=0)
    at nsMenuPopupFrame.cpp:642
#14 0x00007f9b3cfd7d2d in nsXULPopupManager::ShowPopupCallback (
    this=0x7f9b2e1deb00, aPopup=0x7f9b2b304790, aPopupFrame=0x7f9b278a0520, 
    aIsContextMenu=<value optimized out>, 
    aSelectFirstItem=<value optimized out>) at nsXULPopupManager.cpp:599
#15 0x00007f9b3cfd8277 in nsXULPopupManager::FirePopupShowingEvent (
    this=0x7f9b2e1deb00, aPopup=0x7f9b2b304790, aMenu=<value optimized out>, 
    aPresContext=<value optimized out>, aPopupType=ePopupTypeMenu, 
    aIsContextMenu=1, aSelectFirstItem=0) at nsXULPopupManager.cpp:1077
#16 0x00007f9b3cfd8452 in nsXULPopupManager::ShowPopupAtScreen (
    this=0x7f9b2e1deb00, aPopup=0x7f9b2b304790, aXPos=188, aYPos=468, 
    aIsContextMenu=1, aTriggerEvent=<value optimized out>)
    at nsXULPopupManager.cpp:505
#17 0x00007f9b3d26ee6a in nsXULPopupListener::LaunchPopup (
    this=0x7f9b278d4a90, aEvent=0x7f9b21d45058, 
    aTargetContent=<value optimized out>) at nsXULPopupListener.cpp:483
#18 0x00007f9b3d26f36b in nsXULPopupListener::PreLaunchPopup (
    this=0x7f9b278d4a90, aMouseEvent=0x7f9b21d45058)
    at nsXULPopupListener.cpp:253
#19 0x00007f9b3d0520f1 in nsEventListenerManager::HandleEvent (
    this=<value optimized out>, aPresContext=<value optimized out>, 
    aEvent=0x7fffe8003240, aDOMEvent=0x7fffe8002e60, 
    aCurrentTarget=<value optimized out>, aFlags=<value optimized out>, 
    aEventStatus=0x7fffe8002e68) at nsEventListenerManager.cpp:172
#20 0x00007f9b3d066f96 in nsEventTargetChainItem::HandleEvent (
    this=0x7f9b2bd2c3b8, aVisitor=@0x7fffe8002e50, aFlags=514, 
    aMayHaveNewListenerManagers=0) at nsEventDispatcher.cpp:246
#21 0x00007f9b3d067142 in nsEventTargetChainItem::HandleEventTargetChain (
    this=<value optimized out>, aVisitor=@0x7fffe8002e50, aFlags=518, 
    aCallback=0x7fffe8002f20, aMayHaveNewListenerManagers=718272848)
    at nsEventDispatcher.cpp:332
#22 0x00007f9b3d0671c8 in nsEventTargetChainItem::HandleEventTargetChain (
    this=<value optimized out>, aVisitor=@0x7fffe8002e50, aFlags=6, 
    aCallback=0x7fffe8002f20, 
    aMayHaveNewListenerManagers=<value optimized out>)
    at nsEventDispatcher.cpp:362
#23 0x00007f9b3d06774a in nsEventDispatcher::Dispatch (
    aTarget=<value optimized out>, aPresContext=<value optimized out>, 
    aEvent=0x7fffe8003240, aDOMEvent=<value optimized out>, 
    aEventStatus=0x7fffe80030dc, aCallback=<value optimized out>, aTargets=0x0)
    at nsEventDispatcher.cpp:573
#24 0x00007f9b3ced589a in PresShell::HandleEventInternal (this=0x7f9b255b9800, 
    aEvent=0x7fffe8003240, aView=<value optimized out>, aStatus=0x7fffe80030dc)
    at nsPresShell.cpp:6464
#25 0x00007f9b3ced5cf6 in PresShell::HandlePositionedEvent (
    this=0x7f9b255b9800, aView=0x7f9b2c1f5900, aTargetFrame=0x7fffe8002fb0, 
    aEvent=0x7fffe8003240, aEventStatus=0x7fffe80030dc) at nsPresShell.cpp:6310
#26 0x00007f9b3ced667d in PresShell::HandleEvent (this=0x7f9b255b9800, 
    aView=0x7f9b2c1f5900, aEvent=0x7fffe8003240, aEventStatus=0x7fffe80030dc)
    at nsPresShell.cpp:6174
#27 0x00007f9b3d127122 in nsViewManager::HandleEvent (
    this=<value optimized out>, aView=0x7f9b2c1f5900, 
    aPoint=<value optimized out>, aEvent=0x7fffe8003240, 
    aCaptured=<value optimized out>) at nsViewManager.cpp:1224
#28 0x00007f9b3d12975e in nsViewManager::DispatchEvent (this=0x7f9b2c1f5880, 
    aEvent=0x7fffe8003240, aView=<value optimized out>, aStatus=0x7fffe80031ec)
    at nsViewManager.cpp:1203
#29 0x00007f9b3d123dc5 in HandleEvent (aEvent=0x7fffe8003240) at nsView.cpp:167
#30 0x00007f9b3d4d6f75 in nsWindow::DispatchEvent (this=0x7f9b2555dc70, 
    aEvent=<value optimized out>, aStatus=@0x0) at nsWindow.cpp:591
#31 0x00007f9b3d4e0a95 in nsWindow::OnButtonPressEvent (this=0x7f9b2555dc70, 
    aWidget=<value optimized out>, aEvent=0x7f9b21b67cf0) at nsWindow.cpp:2829
#32 0x00007f9b3d4e0ae9 in button_press_event_cb (widget=0x7f9b2c1f4b80, 
    event=0x7f9b21b67cf0) at nsWindow.cpp:5559
#33 0x00007f9b394bdf08 in _gtk_marshal_BOOLEAN__BOXED (closure=0x7f9b2c12fd30, 
    return_value=0x7fffe8003540, n_param_values=<value optimized out>, 
    param_values=0x7f9b21b27820, invocation_hint=<value optimized out>, 
    marshal_data=0x7f9b3d4e0aba) at gtkmarshalers.c:84
#34 0x00007f9b3a0e550a in IA__g_closure_invoke (closure=0x7f9b2c12fd30, 
    return_value=0x7fffe8003540, n_param_values=<value optimized out>, 
    param_values=0x7f9b21b27820, invocation_hint=0x7fffe8003500)
    at gclosure.c:767
#35 0x00007f9b3a0fa86c in signal_emit_unlocked_R (node=0x7f9b3e3d2b00, 
    detail=<value optimized out>, instance=<value optimized out>, 
    emission_return=<value optimized out>, 
    instance_and_params=<value optimized out>) at gsignal.c:3247
#36 0x00007f9b3a0fbaeb in IA__g_signal_emit_valist (instance=0x7f9b2c1f4b80, 
    signal_id=<value optimized out>, detail=0, var_args=0x7fffe80036f0)
    at gsignal.c:2990
#37 0x00007f9b3a0fc163 in IA__g_signal_emit (instance=0x3d0f00, 
    signal_id=718271024, detail=0) at gsignal.c:3037
#38 0x00007f9b395c48af in gtk_widget_event_internal (widget=0x7f9b2c1f4b80, 
    event=0x7f9b21b67cf0) at gtkwidget.c:4767
#39 0x00007f9b394b64b3 in IA__gtk_propagate_event (widget=0x7f9b2c1f4b80, 
    event=0x7f9b21b67cf0) at gtkmain.c:2417
#40 0x00007f9b394b7483 in IA__gtk_main_do_event (event=0x7f9b21b67cf0)
    at gtkmain.c:1622
#41 0x00007f9b38f0ee7c in gdk_event_dispatch (source=<value optimized out>, 
    callback=<value optimized out>, user_data=<value optimized out>)
    at gdkevents-x11.c:2369
#42 0x00007f9b39e303fd in IA__g_main_context_dispatch (context=0x7f9b3e366870)
    at gmain.c:1960
#43 0x00007f9b39e33db8 in g_main_context_iterate (context=0x7f9b3e366870, 
    block=<value optimized out>, dispatch=<value optimized out>, 
    self=<value optimized out>) at gmain.c:2591
#44 0x00007f9b39e33ee0 in IA__g_main_context_iteration (
    context=0x7f9b3e366870, may_block=1) at gmain.c:2654
#45 0x00007f9b3d4f5433 in nsBaseAppShell::DoProcessNextNativeEvent (
    this=0x3d0f00, mayWait=718271024) at nsBaseAppShell.cpp:151
#46 0x00007f9b3d4f5591 in nsBaseAppShell::OnProcessNextEvent (
    this=0x7f9b2e92f160, thr=0x7f9b3e324700, mayWait=1, 
    recursionDepth=<value optimized out>) at nsBaseAppShell.cpp:296
#47 0x00007f9b3d59af01 in nsThread::ProcessNextEvent (this=0x7f9b3e324700, 
    mayWait=1, result=0x7fffe8003abc) at nsThread.cpp:508
#48 0x00007f9b3d56fa0b in NS_ProcessNextEvent_P (thread=0x3d0f00, 
    mayWait=718271024) at nsThreadUtils.cpp:250
#49 0x00007f9b3d4f567d in nsBaseAppShell::Run (this=0x7f9b2e92f160)
    at nsBaseAppShell.cpp:170
#50 0x00007f9b3d3c9366 in nsAppStartup::Run (this=0x7f9b2e9d0900)
    at nsAppStartup.cpp:182
#51 0x00007f9b3cd47347 in XRE_main (argc=<value optimized out>, 
    argv=<value optimized out>, aAppData=<value optimized out>)
    at nsAppRunner.cpp:3483
#52 0x0000000000402963 in ?? ()
#53 0x00007f9b3e93b5dd in __libc_start_main (main=<value optimized out>, 
    argc=<value optimized out>, ubp_av=<value optimized out>, 
    init=<value optimized out>, fini=<value optimized out>, 
    rtld_fini=<value optimized out>, stack_end=0x7fffe8009b58)
    at libc-start.c:226
#54 0x00000000004020f9 in ?? ()
#55 0x00007fffe8009b58 in ?? ()
#56 0x000000000000001c in ?? ()
#57 0x0000000000000002 in ?? ()
#58 0x00007fffe800a0f9 in ?? ()
#59 0x0000000000000000 in ?? ()

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Karl, haven't we had a similar bug in the past months? I cannot find it.

Comment 8

[jez]

Same problem in betas 2 and 5.
Can provoke it any time by killing pulseaudio, can fix it by running pulseaudio.

Suggest that this problem is showing up since the introduction of EVENT_MENU_EXECUTE and EVENT_MENU_POPUP to nsSound::PlayEventSound.
Ideally, libcanberra wouldn't block while it tries to find pulseaudio, but perhaps for the moment we could simply remove those sounds?

widget/src/gtk2/nsSound.cpp:

497,502d496
<         case EVENT_MENU_EXECUTE:
<             ca_context_play(ctx, 0, "event.id", "menu-click", NULL);
<             break;
<         case EVENT_MENU_POPUP:
<             ca_context_play(ctx, 0, "event.id", "menu-popup", NULL);
<             break;
518,521d511
<         else if (aSoundAlias.Equals(NS_SYSSOUND_MENU_EXECUTE))
<             eventId = EVENT_MENU_EXECUTE;
<         else if (aSoundAlias.Equals(NS_SYSSOUND_MENU_POPUP))
<             eventId = EVENT_MENU_POPUP;

Comment 9

[Karl Tomlinson (:karlt)]

This is similar to bug 504670, but that seems to be due to problems with esound, whereas in this bug, the problem seems to be in pulseaudio client code called from libcanberra.

The changes proposed in bug 520417 might help.

Comment 10

[jez]

I submitted http://bugs.freedesktop.org/show_bug.cgi?id=25742 to libcanberra.

Comment 11

[jez]

See also http://pulseaudio.org/ticket/752
The proposals in 520417 look useful anyway, but really I think this has exposed a bug in pulseaudio/libasyncns.

Comment 12

[jez]

Hi

Testing the 3.6 release, I can't produce this delay any more, although I think it was there with the release candidates.

Testing the underlying pulseaudio problem with "PULSE_LOG=99 pactl stat", pulseaudio still will pause for a 5s timeout after a tcp6 error.

So I wonder what happened...

Comment 13

[Karl Tomlinson (:karlt)]

That does sound strange.

Thanks for all your investigation, jez.
I'll mark this WFM for now, but please reopen if the issue returns.

Comment 14

[jez]

I spoke to soon, but I think I got to the bottom of it. The confusion was caused by kernel settings: I thought it was fixed, but actually it was just a ipv6 module getting automatically loaded. The problem still exists when there is no kernel ipv6 support available.

I've submitted a simple patch to pulseaudio which will hopefully be accepted and solve the problem. See http://pulseaudio.org/ticket/752

Comment 15

[jez]

Fixed upstream, use pulseaudio >= 0.9.22 .

Comment 16

[Karl Tomlinson (:karlt)]

Thank you, jez!