Intermittent devtools/debugger/test/browser_dbg_bfcache.js | Test timed out (sometimes followed by an uncaught exception in browser_dbg_breakpoint-new-script.js)

RESOLVED FIXED in Firefox 20

Status

()

Firefox
Developer Tools: Debugger
P3
normal
RESOLVED FIXED
6 years ago
5 years ago

People

(Reporter: emorley, Assigned: jwalker)

Tracking

({intermittent-failure})

15 Branch
Firefox 21
x86
Windows 7
intermittent-failure
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox20 fixed)

Details

Attachments

(2 attachments, 1 obsolete attachment)

(Reporter)

Description

6 years ago
Rev3 MacOSX Leopard 10.5.8 mozilla-beta opt test mochitest-other on 2012-07-16 14:18:38 PDT for push 95f959a8b4dc

slave: talos-r3-leopard-030

https://tbpl.mozilla.org/php/getParsedLog.php?id=13584028&tree=Mozilla-Beta

{
TEST-PASS | chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_gcli_web.js | non-matching selector: html
TEST-PASS | chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_gcli_web.js | multiple matches for head
TEST-PASS | chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_gcli_web.js | non-matching selector: head
TEST-PASS | chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_gcli_web.js | multiple matches for body
TEST-PASS | chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_gcli_web.js | non-matching selector: body
log: Completed test suite
warn: Failed to remove handler from Inputter.onResize
warn: Failed to remove handler from CommandAssignment.onAssignmentChange
INFO TEST-END | chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_gcli_web.js | finished in 2524ms
TEST-INFO | checking window state
TEST-START | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js
TEST-INFO | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Console message: [JavaScript Warning: "Use of Mutation Events is deprecated. Use MutationObserver instead." {file: "chrome://browser/content/orion.js" line: 3408}]
TEST-INFO | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Console message: [JavaScript Warning: "Use of Mutation Events is deprecated. Use MutationObserver instead." {file: "chrome://browser/content/orion.js" line: 3408}]
TEST-INFO | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Console message: [JavaScript Error: "TypeError: gDebuggee.firstCall is not a function: testInitialLoad@chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js:37
@chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js:25
@chrome://mochitests/content/browser/browser/devtools/debugger/test/head.js:150
@resource://gre/modules/devtools/dbg-client.jsm:89
EV_notify@resource://gre/modules/devtools/dbg-client.jsm:149
DC_onPacket@resource://gre/modules/devtools/dbg-client.jsm:415
@chrome://global/content/devtools/dbg-transport.js:170
" {file: "resource://gre/modules/devtools/dbg-client.jsm" line: 153}]
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Test timed out
}
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Priority: -- → P3
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Keywords: intermittent-failure
Whiteboard: [orange]
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Comment 44

6 years ago
past, this seems to have regressed considerably in the last two days - please can you take a look? 

Cheers :-)
Flags: needinfo?(past)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
I think this test is delayed due to the previous tests leaving too much garbage behind, which gets collected at the most inopportune time. I'll whip up a patch with a workaround.
Assignee: nobody → past
Status: NEW → ASSIGNED
Flags: needinfo?(past)
OS: Mac OS X → Windows 7
Created attachment 691463 [details] [diff] [review]
Patch v1

This is what I had in mind. Pushed to try, waiting for results.
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Attachment #691463 - Flags: review?(vporof)
Comment on attachment 691463 [details] [diff] [review]
Patch v1

Review of attachment 691463 [details] [diff] [review]:
-----------------------------------------------------------------

r+ with the file renamed.

::: browser/devtools/debugger/test/Makefile.in
@@ +10,5 @@
>  
>  include $(DEPTH)/config/autoconf.mk
>  
>  MOCHITEST_BROWSER_TESTS = \
> +	browser_dbg_aa_leaktest.js \

Aaa macarenaaaa.. Maybe rename this file to browser-dbg-aaa-run-first-leaktest.js to make things a bit more obvious.

::: browser/devtools/debugger/test/browser_dbg_leaktest.js
@@ +21,5 @@
>    let testStarted = false;
>  
> +  // Wait longer for this very simple test that comes first, to make sure that
> +  // GC from previous tests does not interfere with the debugger suite.
> +  requestLongerTimeout(2);

Sounds reasonable, however I'm not entirely convinced that relying on tests to run in a certain order is bullet-proof enough. Maybe under some other circumstances gc will end up happening during the next test.

But as long as it fixes things, fine by me.
Attachment #691463 - Flags: review?(vporof) → review+
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(In reply to Victor Porof [:vp] from comment #57)
> ::: browser/devtools/debugger/test/browser_dbg_leaktest.js
> @@ +21,5 @@
> >    let testStarted = false;
> >  
> > +  // Wait longer for this very simple test that comes first, to make sure that
> > +  // GC from previous tests does not interfere with the debugger suite.
> > +  requestLongerTimeout(2);
> 
> Sounds reasonable, however I'm not entirely convinced that relying on tests
> to run in a certain order is bullet-proof enough. Maybe under some other
> circumstances gc will end up happening during the next test.
> 
> But as long as it fixes things, fine by me.

My theory is that GCLI tests (or something else before them) are not cleaning up after themselves, but it's hard to make that case with a test as involved as browser_dbg_bfcache.js. By making sure that the debugger suite starts with our equivalent of a no-op, the leak test, whenever only that particular test times out while the other debugger tests are fine, we would have a stringer case to point the finger at tests run before it.
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Updated

6 years ago
Summary: Intermittent devtools/debugger/test/browser_dbg_bfcache.js | Test timed out → Intermittent devtools/debugger/test/browser_dbg_bfcache.js | Test timed out (sometimes followed by an uncaught exception in browser_dbg_breakpoint-new-script.js)
The last one in m-c is with my patch in, and it looks like GC from GCLI tests is still occurring while this test is running. The situation is improved since in this run it timed out while tearing down the test. I should have increased the timeout in this test, not the previous one.
After looking into the last log some more, my theory seems to be confirmed. GCLI tests create a lot of GC activity after finishing, which cuts into the debugger tests runtime. In that log no DOMWindows were released during the last 9 GCLI tests, but they were instead cleaned up during the next two debugger tests (leaktest and bfcache), contending for CPU time. I think the best fix would be to relax a bit the cleanup function here:

http://mxr.mozilla.org/mozilla-central/source/browser/devtools/commandline/test/head.js#65
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Comment 88

6 years ago
https://hg.mozilla.org/mozilla-central/rev/ab30da702673
Status: ASSIGNED → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 20
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
My patch wasn't sufficient, but Joe is working on a patch that should make GCLI tests GC sooner.
Assignee: past → jwalker
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Comment 104

6 years ago
Too many intermittent failures - test disabled on Windows:
https://hg.mozilla.org/integration/mozilla-inbound/rev/245de9e62ca6
Whiteboard: [test disabled on Windows][leave open]
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment on attachment 693372 [details] [diff] [review]
v2

Review of attachment 693372 [details] [diff] [review]:
-----------------------------------------------------------------

Doh, I just remembered about this patch again, you didn't flag me for review.

I'll note that my idea of using executeSoon was to do it for each removeCurrentTab in the loop, making sure that control will return to the event loop in between tab removals. But I expect that the GC request will make a difference, so we can try it even if you don't have the time to amend the patch.
Attachment #693372 - Flags: review+
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Just to clarify my comment 113, I expected to see:
while() { executeSoon() }
instead of:
executeSoon(while() {})

Also, please remember to enable the bfcache test again when you land this.
(In reply to Panos Astithas [:past] from comment #117)
> Just to clarify my comment 113, I expected to see:
> while() { executeSoon() }
> instead of:
> executeSoon(while() {})

Clearly
    while(x) { anythingAsync }

Isn't going to work quite as planned. From the test harness, it looks like everything is forced to be synchronous as soon as we're called from registerCleanupFunction.

http://mxr.mozilla.org/comm-central/source/mozilla/testing/mochitest/browser-test.js#237

I'm going to try again just with force GC and see where that gets us.
(In reply to Joe Walker [:joe_walker] [:jwalker] from comment #118)
> (In reply to Panos Astithas [:past] from comment #117)
> > Just to clarify my comment 113, I expected to see:
> > while() { executeSoon() }
> > instead of:
> > executeSoon(while() {})
> 
> Clearly
>     while(x) { anythingAsync }
> 
> Isn't going to work quite as planned.

I should add that this explains why my original version was borked too.
Created attachment 701769 [details] [diff] [review]
v2.1

https://tbpl.mozilla.org/?tree=Try&rev=0e5b84aa3a4d

Assuming it looks greenish, I think we should run it a few times to be sure.
Attachment #693372 - Attachment is obsolete: true
Attachment #701769 - Flags: review?(past)
Comment on attachment 701769 [details] [diff] [review]
v2.1

Review of attachment 701769 [details] [diff] [review]:
-----------------------------------------------------------------

OK. We need to get some extra runs only on windows I believe.

If this doesn't work, let's just add a longer timeout in the bfcache test as well.
Attachment #701769 - Flags: review?(past) → review+
I think this is fairly green. We've not seen a repeat in 10 runs, so I'm going to land it later today.
Landing in fx-team:

https://tbpl.mozilla.org/?tree=Fx-Team&rev=50ea8eac36c2
https://hg.mozilla.org/integration/fx-team/rev/50ea8eac36c2
Whiteboard: [test disabled on Windows][leave open] → [fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/50ea8eac36c2
Status: REOPENED → RESOLVED
Last Resolved: 6 years ago5 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: Firefox 20 → Firefox 21
Comment on attachment 701769 [details] [diff] [review]
v2.1

[Approval Request Comment]
Bug caused by (feature/regressing bug #): long-standing intermittent test failure
User impact if declined: failures in browser chrome tests in aurora will continue
Testing completed (on m-c, etc.): fx-team and m-c
Risk to taking this patch (and alternatives if risky): test-only change, no risk
String or UUID changes made by this patch: none
Attachment #701769 - Flags: approval-mozilla-aurora?
Ehsan said that test-only changes don't need approval:
https://hg.mozilla.org/releases/mozilla-aurora/rev/09f5bf30cdc0
status-firefox20: --- → fixed
Attachment #701769 - Flags: approval-mozilla-aurora?
Comment hidden (Treeherder Robot)
You need to log in before you can comment on or make changes to this bug.