Closed Bug 1168398 Opened 10 years ago Closed 10 years ago

Intermittent browser_webapi.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - expected PASS

Categories

(Firefox :: Search, defect)

Unspecified
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 44
Tracking Status
e10s + ---
firefox44 --- fixed

People

(Reporter: cbook, Unassigned)

References

(Blocks 1 open bug, )

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Ubuntu VM 12.04 mozilla-inbound debug test mochitest-e10s-browser-chrome-1 https://treeherder.mozilla.org/logviewer.html#?job_id=10147793&repo=mozilla-inbound 04:52:28 INFO - 1168 INFO TEST-UNEXPECTED-FAIL | browser/components/search/test/browser_webapi.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - expected PASS
Inactive; closing (see bug 1180138).
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
This spike is happening because of this repeated assertion it seems (printing assertion backtraces is slow): 19:03:07 INFO - [Child 3138] ###!!! ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /builds/slave/try-lx-d-000000000000000000000/build/src/layout/base/nsPresShell.cpp, line 3442 19:03:07 INFO - #01: PresShell::DoScrollContentIntoView() [layout/base/nsPresShell.cpp:3442] 19:03:07 INFO - #02: PresShell::FlushPendingNotifications(mozilla::ChangesToFlush) [layout/base/nsPresShell.cpp:4135] 19:03:07 INFO - #03: PresShell::FlushPendingNotifications(mozFlushType) [layout/base/nsPresShell.cpp:3970] 19:03:07 INFO - #04: nsDocument::FlushPendingNotifications(mozFlushType) [dom/base/nsDocument.cpp:8233] 19:03:07 INFO - #05: PresShell::ScrollContentIntoView(nsIContent*, nsIPresShell::ScrollAxis, nsIPresShell::ScrollAxis, unsigned int) [layout/base/nsPresShell.cpp:3433] 19:03:07 INFO - #06: nsFocusManager::ScrollIntoView(nsIPresShell*, nsIContent*, unsigned int) [dom/base/nsFocusManager.cpp:2062] 19:03:07 INFO - #07: nsFocusManager::SetFocusInner(nsIContent*, int, bool, bool) [dom/base/nsFocusManager.cpp:1343] 19:03:07 INFO - #08: nsFocusManager::MoveFocus(nsIDOMWindow*, nsIDOMElement*, unsigned int, unsigned int, nsIDOMElement**) [xpcom/glue/nsCOMPtr.h:1405] 19:03:07 INFO - #09: mozilla::dom::TabChild::RecvNavigateByKey(bool const&, bool const&) [dom/ipc/TabChild.cpp:2497] 19:03:07 INFO - #10: mozilla::dom::PBrowserChild::OnMessageReceived(IPC::Message const&) [obj-firefox/ipc/ipdl/PBrowserChild.cpp:4017] 19:03:07 INFO - #11: mozilla::dom::PContentChild::OnMessageReceived(IPC::Message const&) [obj-firefox/ipc/ipdl/PContentChild.cpp:5465] 19:03:07 INFO - #12: mozilla::ipc::MessageChannel::DispatchAsyncMessage(IPC::Message const&) [ipc/glue/MessageChannel.h:520] 19:03:07 INFO - #13: mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message const&) [ipc/glue/MessageChannel.cpp:1302] 19:03:07 INFO - #14: mozilla::ipc::MessageChannel::OnMaybeDequeueOne() [ipc/glue/MessageChannel.cpp:1273] 19:03:07 INFO - #15: RunnableMethod<mozilla::ipc::MessageChannel, bool (mozilla::ipc::MessageChannel::*)(), Tuple0>::Run() [ipc/chromium/src/base/tuple.h:387] 19:03:07 INFO - #16: mozilla::ipc::MessageChannel::DequeueTask::Run() [ipc/glue/MessageChannel.h:459] 19:03:07 INFO - #17: MessageLoop::RunTask(Task*) [ipc/chromium/src/base/message_loop.cc:365] 19:03:07 INFO - #18: MessageLoop::DeferOrRunPendingTask(MessageLoop::PendingTask const&) [ipc/chromium/src/base/message_loop.cc:375] 19:03:07 INFO - #19: MessageLoop::DoWork() [ipc/chromium/src/base/message_loop.cc:459] 19:03:07 INFO - #20: mozilla::ipc::DoWorkRunnable::Run() [ipc/glue/MessagePump.cpp:221] 19:03:07 INFO - #21: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:864] 19:03:07 INFO - #22: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/glue/nsThreadUtils.cpp:277] 19:03:07 INFO - #23: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:96] 19:03:07 INFO - #24: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:234] 19:03:07 INFO - #25: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:520] 19:03:07 INFO - #26: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:158] 19:03:07 INFO - #27: XRE_RunAppShell [toolkit/xre/nsEmbedFunctions.cpp:785] 19:03:07 INFO - #28: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:259] 19:03:07 INFO - #29: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:234] 19:03:07 INFO - #30: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:520] 19:03:07 INFO - #31: XRE_InitChildProcess [toolkit/xre/nsEmbedFunctions.cpp:625] 19:03:07 INFO - #32: content_process_main(int, char**) [ipc/contentproc/plugin-container.cpp:238] 19:03:07 INFO - #33: main [ipc/app/MozillaRuntimeMain.cpp:12] This is an example log from a few days ago without this assertion: <http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-linux64-debug/1439779237/mozilla-inbound_ubuntu64_vm-debug_test-mochitest-e10s-browser-chrome-1-bm121-tests1-linux64-build124.txt.gz> Something has recently changes to make this assertion happen. It would be nice to figure out what.
tracking-e10s: --- → ?
(In reply to Ehsan Akhgari (don't ask for review please) from comment #36) > This spike is happening because of this repeated assertion it seems > (printing assertion backtraces is slow): > > 19:03:07 INFO - [Child 3138] ###!!! ASSERTION: should have done initial > reflow by now: 'mDidInitialize', file > /builds/slave/try-lx-d-000000000000000000000/build/src/layout/base/ > nsPresShell.cpp, line 3442 > 19:03:07 INFO - #01: PresShell::DoScrollContentIntoView() > [layout/base/nsPresShell.cpp:3442] > 19:03:07 INFO - #02: > PresShell::FlushPendingNotifications(mozilla::ChangesToFlush) > [layout/base/nsPresShell.cpp:4135] > 19:03:07 INFO - #03: PresShell::FlushPendingNotifications(mozFlushType) > [layout/base/nsPresShell.cpp:3970] > 19:03:07 INFO - #04: > nsDocument::FlushPendingNotifications(mozFlushType) > [dom/base/nsDocument.cpp:8233] > 19:03:07 INFO - #05: PresShell::ScrollContentIntoView(nsIContent*, > nsIPresShell::ScrollAxis, nsIPresShell::ScrollAxis, unsigned int) > [layout/base/nsPresShell.cpp:3433] > 19:03:07 INFO - #06: nsFocusManager::ScrollIntoView(nsIPresShell*, > nsIContent*, unsigned int) [dom/base/nsFocusManager.cpp:2062] > 19:03:07 INFO - #07: nsFocusManager::SetFocusInner(nsIContent*, int, > bool, bool) [dom/base/nsFocusManager.cpp:1343] > 19:03:07 INFO - #08: nsFocusManager::MoveFocus(nsIDOMWindow*, > nsIDOMElement*, unsigned int, unsigned int, nsIDOMElement**) > [xpcom/glue/nsCOMPtr.h:1405] > 19:03:07 INFO - #09: mozilla::dom::TabChild::RecvNavigateByKey(bool > const&, bool const&) [dom/ipc/TabChild.cpp:2497] > 19:03:07 INFO - #10: > mozilla::dom::PBrowserChild::OnMessageReceived(IPC::Message const&) > [obj-firefox/ipc/ipdl/PBrowserChild.cpp:4017] > 19:03:07 INFO - #11: > mozilla::dom::PContentChild::OnMessageReceived(IPC::Message const&) > [obj-firefox/ipc/ipdl/PContentChild.cpp:5465] > 19:03:07 INFO - #12: > mozilla::ipc::MessageChannel::DispatchAsyncMessage(IPC::Message const&) > [ipc/glue/MessageChannel.h:520] > 19:03:07 INFO - #13: > mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message const&) > [ipc/glue/MessageChannel.cpp:1302] > 19:03:07 INFO - #14: mozilla::ipc::MessageChannel::OnMaybeDequeueOne() > [ipc/glue/MessageChannel.cpp:1273] > 19:03:07 INFO - #15: RunnableMethod<mozilla::ipc::MessageChannel, bool > (mozilla::ipc::MessageChannel::*)(), Tuple0>::Run() > [ipc/chromium/src/base/tuple.h:387] > 19:03:07 INFO - #16: mozilla::ipc::MessageChannel::DequeueTask::Run() > [ipc/glue/MessageChannel.h:459] > 19:03:07 INFO - #17: MessageLoop::RunTask(Task*) > [ipc/chromium/src/base/message_loop.cc:365] > 19:03:07 INFO - #18: > MessageLoop::DeferOrRunPendingTask(MessageLoop::PendingTask const&) > [ipc/chromium/src/base/message_loop.cc:375] > 19:03:07 INFO - #19: MessageLoop::DoWork() > [ipc/chromium/src/base/message_loop.cc:459] > 19:03:07 INFO - #20: mozilla::ipc::DoWorkRunnable::Run() > [ipc/glue/MessagePump.cpp:221] > 19:03:07 INFO - #21: nsThread::ProcessNextEvent(bool, bool*) > [xpcom/threads/nsThread.cpp:864] > 19:03:07 INFO - #22: NS_ProcessNextEvent(nsIThread*, bool) > [xpcom/glue/nsThreadUtils.cpp:277] > 19:03:07 INFO - #23: > mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) > [ipc/glue/MessagePump.cpp:96] > 19:03:07 INFO - #24: MessageLoop::RunInternal() > [ipc/chromium/src/base/message_loop.cc:234] > 19:03:07 INFO - #25: MessageLoop::Run() > [ipc/chromium/src/base/message_loop.cc:520] > 19:03:07 INFO - #26: nsBaseAppShell::Run() > [widget/nsBaseAppShell.cpp:158] > 19:03:07 INFO - #27: XRE_RunAppShell > [toolkit/xre/nsEmbedFunctions.cpp:785] > 19:03:07 INFO - #28: > mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) > [ipc/glue/MessagePump.cpp:259] > 19:03:07 INFO - #29: MessageLoop::RunInternal() > [ipc/chromium/src/base/message_loop.cc:234] > 19:03:07 INFO - #30: MessageLoop::Run() > [ipc/chromium/src/base/message_loop.cc:520] > 19:03:07 INFO - #31: XRE_InitChildProcess > [toolkit/xre/nsEmbedFunctions.cpp:625] > 19:03:07 INFO - #32: content_process_main(int, char**) > [ipc/contentproc/plugin-container.cpp:238] > 19:03:07 INFO - #33: main [ipc/app/MozillaRuntimeMain.cpp:12] > > This is an example log from a few days ago without this assertion: > <http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla- > inbound-linux64-debug/1439779237/mozilla-inbound_ubuntu64_vm-debug_test- > mochitest-e10s-browser-chrome-1-bm121-tests1-linux64-build124.txt.gz> > > Something has recently changes to make this assertion happen. It would be > nice to figure out what. Kats, do you recall any scrolling-related changes that might have triggered this?
Flags: needinfo?(bugmail.mozilla)
There's nothing APZ-related on the stack, but I notice the function TabChild::RecvNavigateByKey() on the stack, was added in bug 1132518 (under the name NavigateDocument(), then renamed in bug 1176239), on July 13, around the same time this intermittent started firing. Perhaps Neil might be able to shed some light on this?
Flags: needinfo?(bugmail.mozilla) → needinfo?(enndeakin)
The stack suggests a test is pressing the tab key to move focus from chrome to the content process. A quick glance suggests that the previous test synthesizes tab key presses, but I don't know if it does this between process boundaries. Maybe the message is getting delayed and firing when the test next is being loaded but not yet ready.
Flags: needinfo?(enndeakin)
In the log in comment 592 at least the assertions are showing up under browser/components/search/test/browser_searchbar_keyboard_navigation.js and browser/components/search/test/browser_searchbar_smallpanel_keyboard_navigation.js but not under browser_webapi.js. So I don't think the assertion is to blame for the test's slowness. Somebody who understands the test should look into this (CC'd :mossop who appears to be the owner based on the file history).
(In reply to Kartikaya Gupta (email:kats@mozilla.com) from comment #593) > In the log in comment 592 at least the assertions are showing up under > browser/components/search/test/browser_searchbar_keyboard_navigation.js and > browser/components/search/test/ > browser_searchbar_smallpanel_keyboard_navigation.js but not under > browser_webapi.js. So I don't think the assertion is to blame for the test's > slowness. Somebody who understands the test should look into this (CC'd > :mossop who appears to be the owner based on the file history). Are the timestamps shown in these logs to be trusted? The most recent one shows browser_webapi.js starting at 22:45:57 and being timed out at 22:46:01 but then says that the test took 50224ms. That doesn't match up so either the test harness isn't timing things properly which means this test isn't at fault, or the timestamps aren't correct which makes it hard to figure out where the time is going here. The test does open 12 modal dialogs and these can be slow on debug builds so it is possible that it is just slow, it would be nice to look back and see if it used to be faster.
I was under the impression that the log output gets buffered by the harness and then dumped all at once when the test ends. So the timestamps on the log output is generally for when the test ends and the output gets dumped, rather than from when the output was actually created by the test. I could be wrong though.
As far as I can tell, this has gone pretty much perma-orange on m-c now. :/ Any chance we can disable this test until we know what's going on?
> Any chance we can disable this test until we know what's going on? The assertions are caused by the previous test so disabling this test might not fix this.
FWIW this is almost 100% reproducible by running `./mach mochitest -f browser --e10s browser/components/search`. What's happening here is that we are trying to scroll a node into view on an about:blank document that hasn't been layed out yet. The fix is simple, we need to check to see if the presshell is initialized before using it.
Attachment #8666475 - Flags: review?(enndeakin) → review+
Status: REOPENED → RESOLVED
Closed: 10 years ago10 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 44
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: