Closed Bug 774619 Opened 7 years ago Closed 7 years ago

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

Categories

(DevTools :: Debugger, defect, P3)

15 Branch
x86
Windows 7
defect

Tracking

(firefox20 fixed)

RESOLVED FIXED
Firefox 21
Tracking Status
firefox20 --- fixed

People

(Reporter: emorley, Assigned: jwalker)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

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
}
Priority: -- → P3
Whiteboard: [orange]
past, this seems to have regressed considerably in the last two days - please can you take a look? 

Cheers :-)
Flags: needinfo?(past)
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
Attached patch Patch v1Splinter Review
This is what I had in mind. Pushed to try, waiting for results.
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+
(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.
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
https://hg.mozilla.org/mozilla-central/rev/ab30da702673
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 20
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 → ---
Too many intermittent failures - test disabled on Windows:
https://hg.mozilla.org/integration/mozilla-inbound/rev/245de9e62ca6
Whiteboard: [test disabled on Windows][leave open]
Attached patch v2 (obsolete) — Splinter Review
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+
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.
Attached patch v2.1Splinter Review
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
Closed: 7 years ago7 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?
Attachment #701769 - Flags: approval-mozilla-aurora?
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.