Closed Bug 1342927 Opened 7 years ago Closed 7 years ago

Don't wait for a layer tree if the TabChild hasn't actually been created yet

Categories

(Core :: DOM: Content Processes, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla55
Tracking Status
firefox55 --- fixed

People

(Reporter: mconley, Unassigned)

References

Details

Attachments

(7 files)

STR:

0) Set dom.ipc.processCount to 1 for an easier time reproducing.
1) Block the content process. A while(true) {} in a web console is a great way to do this.
2) Open the Browser Console, and type this in: 

gBrowser.loadOneTab("https://www.mozilla.ca", { inBackground:true });

3) A title-less background tab will open. Try to switch to it.

ER:

Probably a blank tab, in this configuration.

AR:

The ~300ms delay, and then a perma tab-switch spinner.


What's happening here is that the content process is blocked, and can't respond to the parent's request to construct a TabChild (since in this scenario, the parent is requesting that a tab opens, and not the child). When the tab is switched to, properly message the ProcessHangMonitor thread and tell it to try to force paint the tab that we're switching to, but bail out here:

http://searchfox.org/mozilla-central/rev/90d1cbb4fd3dc249cdc11fe5c3e0394d22d9c680/dom/ipc/ProcessHangMonitor.cpp#318-321

Because it can't find the not-yet-created TabChild.

In this case, I suspect we should just paint blank. Either we have the ProcessHangMonitor somehow kick off some mechanism to send a blank frame to the compositor, or (maybe even better) the parent should know when a TabChild has been created, and if it hasn't yet, it should know to just paint blank instead of kicking off the force paint infrastructure.

billm, any preference on how to proceed here?
Flags: needinfo?(wmccloskey)
Blocks: 1300411
Talked with billm and kats about this. Most straight-forward way to do this, probably, is to have the PHM tell the parent that the TabChild doesn't exist, and have it react (by completing the switch to a blank tab).
Flags: needinfo?(wmccloskey)
Another wrinkle - it's possible, especially if the content process has _just_ been started, that the HangMonitorChild hasn't been set up just yet. I'm pretty sure that means that the message from the parent to force tab switch will be queued until the HangMonitorChild is instantiated and can consume it - but even then, there's still a pocket of time where the TabChild probably hasn't been created yet, and the force painting will not occur.

What I propose:

1) Add a (hang monitor thread-only) mReady bool to HangMonitorParent that inits to false. When HangMonitorChild::Bind is called, the HangMonitorChild sends a message to the parent saying that it's ready. HangMonitorParent flips the mReady bool to true.

2) When the HangMonitorParent background thread is asked to force-paint a tab, it should look to see whether mReady is true. If not, it should send a message back to the main thread saying, "I'm still waiting on a TabChild", which should fire an event which tabbrowser.xml can then interpret to do something sensible (I'm thinking complete the tab switch and just show a blank tab).

3) If mReady is true, send the ForceTabPaint message to the HangMonitorChild background thread, and have it interrupt JS and try to force paint the TabChild associated with the tabId. If no TabChild can be found for that tabId, message the parent, and the parent should then fire that same "I'm still waiting on a TabChild" event to tabbrowser.xml.

I think this should take care of a significant number of spinners that tend to occur early in the lifetime of a tab (or content process).
Blocks: 1343639
Comment on attachment 8842207 [details]
Bug 1342927 - Fire a MozTabChildNotReady event on a frameloader if force-painting a tab without a TabChild.

https://reviewboard.mozilla.org/r/116098/#review118034

::: dom/ipc/ProcessHangMonitor.cpp:670
(Diff revision 1)
> +      // a new content process that probably hasn't had time to
> +      // get the ContentChild, let alone the TabChild for aTabId,
> +      // set up, and so attempting to force paint on the non-existant
> +      // TabChild is not going to work. Instead, we tell the main
> +      // thread that we're waiting on a TabChild to be created.
> +      mMainThreadLoop->PostTask(

I misdirected you yesterday. You can just use NS_DispatchToMainThread with this runnable. No need to save mMainThreadLoop.

::: dom/ipc/ProcessHangMonitor.cpp:774
(Diff revision 1)
>  }
>  
>  mozilla::ipc::IPCResult
> +HangMonitorParent::RecvReady()
> +{
> +  mReady = true;

Please add:
MOZ_RELEASE_ASSERT(MessageLoop::current() == MonitorLoop());
Attachment #8842207 - Flags: review?(wmccloskey) → review+
Comment on attachment 8842554 [details]
Bug 1342927 - Make async tab switcher show a blank tab when switching to tabs that have no TabChild yet.

https://reviewboard.mozilla.org/r/116338/#review118042

::: browser/base/content/tabbrowser.css:107
(Diff revision 1)
>    opacity: 0;
>  }
>  
> +tabbrowser[pendingtabchild],
> +tabbrowser[pendingpaint] {
> +  background-color: #f9f9f9 !important;

So it will be very light gray instead of white? Is that what we want?

::: browser/base/content/tabbrowser.xml:4219
(Diff revision 1)
>  
> +            // The tab for this browser isn't currently set
> +            // up in the content process, so we have no chance
> +            // of painting it right away. We'll paint a blank
> +            // tab instead.
> +            onTabChildNotReady(browser) {

You might want to futz with the telemetry here. We won't count this as a spinner, but it will still hurt our tab switch time. It probably shouldn't.

::: browser/base/content/tabbrowser.xml:4222
(Diff revision 1)
> +            // of painting it right away. We'll paint a blank
> +            // tab instead.
> +            onTabChildNotReady(browser) {
> +              let tab = this.tabbrowser.getTabForBrowser(browser);
> +              this.pendingTabChild.add(browser);
> +              this.setTabState(tab, this.STATE_LOADING);

Shouldn't the state already be STATE_LOADING? What other state could we be in? Could you assert here instead?

::: browser/base/content/tabbrowser.xml:4224
(Diff revision 1)
> +              if (this.loadingTab === tab) {
> +                this.clearTimer(this.loadTimer);
> +                this.loadTimer = null;
> +                this.loadingTab = null;
> +              }

I'm not sure this code is necessary, but I can't see it hurting either, I guess.
Attachment #8842554 - Flags: review?(wmccloskey) → review+
Comment on attachment 8842576 [details]
Bug 1342927 - Add a hidden pref to disable force painting of tabs so that browser_tabSpinnerProbe.js can pass.

https://reviewboard.mozilla.org/r/116360/#review118052

::: dom/ipc/ProcessHangMonitor.cpp:211
(Diff revision 1)
>    ContentParent* mContentParent;
>    HangData mHangData;
>    nsAutoString mDumpId;
>  };
>  
> +

Please remove the extra line.
Attachment #8842576 - Flags: review?(wmccloskey) → review+
Comment on attachment 8842554 [details]
Bug 1342927 - Make async tab switcher show a blank tab when switching to tabs that have no TabChild yet.

https://reviewboard.mozilla.org/r/116338/#review118042

> So it will be very light gray instead of white? Is that what we want?

Probably not. I'll switch it to white for now, thanks.

> You might want to futz with the telemetry here. We won't count this as a spinner, but it will still hurt our tab switch time. It probably shouldn't.

Good call. Since we're effectively disguising the fact that the TabChild hasn't uploaded the layer tree yet, I'm considering this a completed tab switch (even though the switcher is still waiting on those layers). I'm calling `maybeFinishTabSwitch` now, and have modified that function to account for the possibility that we've switched to the `blankTab`.

> Shouldn't the state already be STATE_LOADING? What other state could we be in? Could you assert here instead?

I needed this because I was getting perma-blank tabs on the selected tab after restoration. It turns out this is because the switcher was `finish`ing early and not hearing the `MozLayerTreeReady` event, because we don't switch the state back to `STATE_LOADING` when flipping from non-remote to remote. I've updated `onRemotenessChange` for that, and I also have it toss the browser into the `pendingTabChild` set so that we don't show a brief spinner after the remoteness change event.

> I'm not sure this code is necessary, but I can't see it hurting either, I guess.

I guess I want to avoid side-effects where possible. The tab switcher is already pretty complicated, so I'm trying to nip this timeout case in the bud if we _know_ we've requested a tab that has no TabChild ready for it.
Hey billm,

Thanks for the reviews! I've updated the tabbrowser switcher code per suggestions (comment 9), and here's the interdiff:

https://reviewboard.mozilla.org/r/116338/diff/1-3/

Any objections, or can I go ahead and land this?
Flags: needinfo?(wmccloskey)
Pushed by mconley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7b38f4123214
Fire a MozTabChildNotReady event on a frameloader if force-painting a tab without a TabChild. r=billm
https://hg.mozilla.org/integration/autoland/rev/692743c2995e
Make async tab switcher show a blank tab when switching to tabs that have no TabChild yet. r=billm
https://hg.mozilla.org/integration/autoland/rev/bba8780c5312
Add a hidden pref to disable force painting of tabs so that browser_tabSpinnerProbe.js can pass. r=billm
Backed out for asserting @chrome://browser/content/tabbrowser.xml:3995:25:

https://hg.mozilla.org/integration/autoland/rev/0f6c81e7bb41d55bcf629c2f4e5f16efbcf1c238
https://hg.mozilla.org/integration/autoland/rev/5e950d79f1b57180a0f3a1e31ceb31141e1aeeee
https://hg.mozilla.org/integration/autoland/rev/a25b3225e35191dbd368195852b86da57cdcc7a5

Push with failure: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=bba8780c5312ebdaf798fc12152ed13075ad2d2c&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=81525324&repo=autoland

[task 2017-03-03T19:19:21.550860Z] 19:19:21     INFO - Assertion failure
[task 2017-03-03T19:19:21.551381Z] 19:19:21     INFO - assert@chrome://browser/content/tabbrowser.xml:3991:46
[task 2017-03-03T19:19:21.551687Z] 19:19:21     INFO - onTabChildNotReady@chrome://browser/content/tabbrowser.xml:4306:15
[task 2017-03-03T19:19:21.553465Z] 19:19:21     INFO - handleEvent@chrome://browser/content/tabbrowser.xml:4373:17
[task 2017-03-03T19:19:21.553880Z] 19:19:21     INFO - EventListener.handleEvent*init@chrome://browser/content/tabbrowser.xml:3839:15
[task 2017-03-03T19:19:21.556167Z] 19:19:21     INFO - _getSwitcher@chrome://browser/content/tabbrowser.xml:4507:11
[task 2017-03-03T19:19:21.556576Z] 19:19:21     INFO - set_selectedIndex@chrome://browser/content/tabbrowser.xml:7704:11
[task 2017-03-03T19:19:21.559600Z] 19:19:21     INFO - set_selectedPanel@chrome://global/content/bindings/tabbox.xml:703:13
[task 2017-03-03T19:19:21.561633Z] 19:19:21     INFO - set_selectedIndex@chrome://global/content/bindings/tabbox.xml:409:15
[task 2017-03-03T19:19:21.567234Z] 19:19:21     INFO - set_selectedItem@chrome://global/content/bindings/tabbox.xml:441:34
[task 2017-03-03T19:19:21.569260Z] 19:19:21     INFO - set_selectedTab@chrome://global/content/bindings/tabbox.xml:111:15
[task 2017-03-03T19:19:21.575306Z] 19:19:21     INFO - set_selectedTab@chrome://browser/content/tabbrowser.xml:3332:11
[task 2017-03-03T19:19:21.577490Z] 19:19:21     INFO - _blurTab@chrome://browser/content/tabbrowser.xml:2899:13
[task 2017-03-03T19:19:21.580569Z] 19:19:21     INFO - _endRemoveTab@chrome://browser/content/tabbrowser.xml:2763:13
[task 2017-03-03T19:19:21.582461Z] 19:19:21     INFO - removeTab@chrome://browser/content/tabbrowser.xml:2598:15
[task 2017-03-03T19:19:21.584580Z] 19:19:21     INFO - Tester_waitForWindowsState@chrome://mochikit/content/browser-test.js:297:7
[task 2017-03-03T19:19:21.591884Z] 19:19:21     INFO - Tester.prototype.nextTest<@chrome://mochikit/content/browser-test.js:567:5
[task 2017-03-03T19:19:21.593831Z] 19:19:21     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-03T19:19:21.595952Z] 19:19:21     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-03T19:19:21.598958Z] 19:19:21     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:21.601213Z] 19:19:21     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:21.603976Z] 19:19:21     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:21.607372Z] 19:19:21     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:21.612589Z] 19:19:21     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:21.614528Z] 19:19:21     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:21.617213Z] 19:19:21     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:21.619199Z] 19:19:21     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:21.624685Z] 19:19:21     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:21.626605Z] 19:19:21     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:21.628425Z] 19:19:21     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:21.630337Z] 19:19:21     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-03T19:19:21.634329Z] 19:19:21     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-03T19:19:21.636496Z] 19:19:21     INFO - testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1006:11
[task 2017-03-03T19:19:21.638386Z] 19:19:21     INFO - run@chrome://mochikit/content/browser-test.js:937:9
[task 2017-03-03T19:19:21.640428Z] 19:19:21     INFO - TEST-INFO | started process screentopng
[task 2017-03-03T19:19:24.424386Z] 19:19:24     INFO - TEST-INFO | screentopng: exit 0
[task 2017-03-03T19:19:24.431538Z] 19:19:24     INFO - Buffered messages logged at 19:19:08
[task 2017-03-03T19:19:24.433891Z] 19:19:24     INFO - Entering test bound setup
[task 2017-03-03T19:19:24.436251Z] 19:19:24     INFO - Leaving test bound setup
[task 2017-03-03T19:19:24.440983Z] 19:19:24     INFO - Entering test bound test_form_data_restoration
[task 2017-03-03T19:19:24.444598Z] 19:19:24     INFO - Buffered messages logged at 19:19:17
[task 2017-03-03T19:19:24.446647Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[@name='input']" was correctly restored - 
[task 2017-03-03T19:19:24.451080Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[@name='spaced 1']" was correctly restored - 
[task 2017-03-03T19:19:24.452914Z] 19:19:24     INFO - Buffered messages logged at 19:19:18
[task 2017-03-03T19:19:24.456751Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[3]" was correctly restored - 
[task 2017-03-03T19:19:24.458811Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[@type='checkbox']" was correctly restored - 
[task 2017-03-03T19:19:24.464876Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[@name='uncheck']" was correctly restored - 
[task 2017-03-03T19:19:24.467147Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[@type='radio'][1]" was correctly restored - 
[task 2017-03-03T19:19:24.469926Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[@type='radio'][2]" was correctly restored - 
[task 2017-03-03T19:19:24.471931Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[@type='radio'][3]" was correctly restored - 
[task 2017-03-03T19:19:24.474173Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//select" was correctly restored - 
[task 2017-03-03T19:19:24.476560Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//select[@multiple]" was correctly restored - 
[task 2017-03-03T19:19:24.479692Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//textarea[1]" was correctly restored - 
[task 2017-03-03T19:19:24.482417Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//textarea[2]" was correctly restored - 
[task 2017-03-03T19:19:24.484591Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//textarea[3]" was correctly restored - 
[task 2017-03-03T19:19:24.490205Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[@type='file'][1]" was correctly restored - 
[task 2017-03-03T19:19:24.492263Z] 19:19:24     INFO - TEST-PASS | browser/components/sessionstore/test/browser_formdata_xpath.js | The value for "//input[@type='file'][2]" was correctly restored - 
[task 2017-03-03T19:19:24.499235Z] 19:19:24     INFO - Buffered messages finished
[task 2017-03-03T19:19:24.502210Z] 19:19:24     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_formdata_xpath.js | uncaught exception - Error: Assertion failure at assert@chrome://browser/content/tabbrowser.xml:3995:25
[task 2017-03-03T19:19:24.504273Z] 19:19:24     INFO - onTabChildNotReady@chrome://browser/content/tabbrowser.xml:4306:15
[task 2017-03-03T19:19:24.508727Z] 19:19:24     INFO - handleEvent@chrome://browser/content/tabbrowser.xml:4373:17
[task 2017-03-03T19:19:24.510853Z] 19:19:24     INFO - EventListener.handleEvent*init@chrome://browser/content/tabbrowser.xml:3839:15
[task 2017-03-03T19:19:24.514234Z] 19:19:24     INFO - _getSwitcher@chrome://browser/content/tabbrowser.xml:4507:11
[task 2017-03-03T19:19:24.518174Z] 19:19:24     INFO - set_selectedIndex@chrome://browser/content/tabbrowser.xml:7704:11
[task 2017-03-03T19:19:24.519906Z] 19:19:24     INFO - set_selectedPanel@chrome://global/content/bindings/tabbox.xml:703:13
[task 2017-03-03T19:19:24.522372Z] 19:19:24     INFO - set_selectedIndex@chrome://global/content/bindings/tabbox.xml:409:15
[task 2017-03-03T19:19:24.524112Z] 19:19:24     INFO - set_selectedItem@chrome://global/content/bindings/tabbox.xml:441:34
[task 2017-03-03T19:19:24.528468Z] 19:19:24     INFO - set_selectedTab@chrome://global/content/bindings/tabbox.xml:111:15
[task 2017-03-03T19:19:24.530253Z] 19:19:24     INFO - set_selectedTab@chrome://browser/content/tabbrowser.xml:3332:11
[task 2017-03-03T19:19:24.531931Z] 19:19:24     INFO - _blurTab@chrome://browser/content/tabbrowser.xml:2899:13
[task 2017-03-03T19:19:24.533760Z] 19:19:24     INFO - _endRemoveTab@chrome://browser/content/tabbrowser.xml:2763:13
[task 2017-03-03T19:19:24.535679Z] 19:19:24     INFO - removeTab@chrome://browser/content/tabbrowser.xml:2598:15
[task 2017-03-03T19:19:24.538632Z] 19:19:24     INFO - Tester_waitForWindowsState@chrome://mochikit/content/browser-test.js:297:7
[task 2017-03-03T19:19:24.541084Z] 19:19:24     INFO - Tester.prototype.nextTest<@chrome://mochikit/content/browser-test.js:567:5
[task 2017-03-03T19:19:24.543468Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-03T19:19:24.545532Z] 19:19:24     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-03T19:19:24.551609Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.553703Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.555863Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.559716Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.563215Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.565252Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.569604Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.571394Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.573264Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.575195Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.578110Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.579883Z] 19:19:24     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-03T19:19:24.582976Z] 19:19:24     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-03T19:19:24.585022Z] 19:19:24     INFO - testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1006:11
[task 2017-03-03T19:19:24.586766Z] 19:19:24     INFO - run@chrome://mochikit/content/browser-test.js:937:9
[task 2017-03-03T19:19:24.588602Z] 19:19:24     INFO - 
[task 2017-03-03T19:19:24.590585Z] 19:19:24     INFO - Stack trace:
[task 2017-03-03T19:19:24.592786Z] 19:19:24     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:simpletestOnerror:1648
[task 2017-03-03T19:19:24.595035Z] 19:19:24     INFO - JavaScript error: chrome://browser/content/tabbrowser.xml, line 3995: Error: Assertion failure
[task 2017-03-03T19:19:24.598176Z] 19:19:24     INFO - ++DOMWINDOW == 98 (0x7f6a1d6c0000) [pid = 1285] [serial = 1773] [outer = 0x7f6a1ce71c00]
[task 2017-03-03T19:19:24.600558Z] 19:19:24     INFO - Console message: [JavaScript Error: "Error: Assertion failure" {file: "chrome://browser/content/tabbrowser.xml" line: 3995}]
[task 2017-03-03T19:19:24.607748Z] 19:19:24     INFO - assert@chrome://browser/content/tabbrowser.xml:3995:25
[task 2017-03-03T19:19:24.611771Z] 19:19:24     INFO - onTabChildNotReady@chrome://browser/content/tabbrowser.xml:4306:15
[task 2017-03-03T19:19:24.613657Z] 19:19:24     INFO - handleEvent@chrome://browser/content/tabbrowser.xml:4373:17
[task 2017-03-03T19:19:24.615468Z] 19:19:24     INFO - EventListener.handleEvent*init@chrome://browser/content/tabbrowser.xml:3839:15
[task 2017-03-03T19:19:24.617556Z] 19:19:24     INFO - _getSwitcher@chrome://browser/content/tabbrowser.xml:4507:11
[task 2017-03-03T19:19:24.619822Z] 19:19:24     INFO - set_selectedIndex@chrome://browser/content/tabbrowser.xml:7704:11
[task 2017-03-03T19:19:24.621763Z] 19:19:24     INFO - set_selectedPanel@chrome://global/content/bindings/tabbox.xml:703:13
[task 2017-03-03T19:19:24.625873Z] 19:19:24     INFO - set_selectedIndex@chrome://global/content/bindings/tabbox.xml:409:15
[task 2017-03-03T19:19:24.628271Z] 19:19:24     INFO - set_selectedItem@chrome://global/content/bindings/tabbox.xml:441:34
[task 2017-03-03T19:19:24.632099Z] 19:19:24     INFO - set_selectedTab@chrome://global/content/bindings/tabbox.xml:111:15
[task 2017-03-03T19:19:24.634105Z] 19:19:24     INFO - set_selectedTab@chrome://browser/content/tabbrowser.xml:3332:11
[task 2017-03-03T19:19:24.636129Z] 19:19:24     INFO - _blurTab@chrome://browser/content/tabbrowser.xml:2899:13
[task 2017-03-03T19:19:24.638174Z] 19:19:24     INFO - _endRemoveTab@chrome://browser/content/tabbrowser.xml:2763:13
[task 2017-03-03T19:19:24.641873Z] 19:19:24     INFO - removeTab@chrome://browser/content/tabbrowser.xml:2598:15
[task 2017-03-03T19:19:24.643633Z] 19:19:24     INFO - Tester_waitForWindowsState@chrome://mochikit/content/browser-test.js:297:7
[task 2017-03-03T19:19:24.645499Z] 19:19:24     INFO - Tester.prototype.nextTest<@chrome://mochikit/content/browser-test.js:567:5
[task 2017-03-03T19:19:24.647254Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-03T19:19:24.649114Z] 19:19:24     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-03T19:19:24.653198Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.655055Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.656743Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.658682Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.660617Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.662655Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.664483Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.670759Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.675003Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.676922Z] 19:19:24     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7
[task 2017-03-03T19:19:24.679715Z] 19:19:24     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-03T19:19:24.681464Z] 19:19:24     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-03T19:19:24.683352Z] 19:19:24     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-03T19:19:24.685372Z] 19:19:24     INFO - testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1006:11
[task 2017-03-03T19:19:24.688438Z] 19:19:24     INFO - run@chrome://mochikit/content/browser-test.js:937:9
[task 2017-03-03T19:19:24.690478Z] 19:19:24     INFO -
Flags: needinfo?(mconley)
Flags: needinfo?(wmccloskey)
Pushed by mconley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2f9561ccd777
Fire a MozTabChildNotReady event on a frameloader if force-painting a tab without a TabChild. r=billm
https://hg.mozilla.org/integration/autoland/rev/9d44c499c3db
Make async tab switcher show a blank tab when switching to tabs that have no TabChild yet. r=billm
https://hg.mozilla.org/integration/autoland/rev/7d79c8090f75
Add a hidden pref to disable force painting of tabs so that browser_tabSpinnerProbe.js can pass. r=billm
Backed out for asserting at chrome://browser/content/tabbrowser.xml:3995:25 e.g. in browser/browser_menu_item_01.js:

https://hg.mozilla.org/integration/autoland/rev/d3fb96a2c6ef0d08a1037d3503882eea9fd2ecb5
https://hg.mozilla.org/integration/autoland/rev/89d3e87de3e63979540a8f6dac0c9ebc941c327a
https://hg.mozilla.org/integration/autoland/rev/b51280e3f8e6c7841da59a005fed1c83b3f11d42

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=7d79c8090f75d66a1c39821273d5760fdb94a23e&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=81620658&repo=autoland

[task 2017-03-04T05:47:43.706230Z] 05:47:43     INFO - TEST-PASS | devtools/client/responsive.html/test/browser/browser_menu_item_01.js | RDM menu item is unchecked after RDM is closed - 
[task 2017-03-04T05:47:43.722708Z] 05:47:43     INFO - Removing tab.
[task 2017-03-04T05:47:43.722777Z] 05:47:43     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2017-03-04T05:47:43.831789Z] 05:47:43     INFO - Assertion failure
[task 2017-03-04T05:47:43.831893Z] 05:47:43     INFO - assert@chrome://browser/content/tabbrowser.xml:3991:46
[task 2017-03-04T05:47:43.831946Z] 05:47:43     INFO - finish@chrome://browser/content/tabbrowser.xml:3878:15
[task 2017-03-04T05:47:43.831993Z] 05:47:43     INFO - postActions@chrome://browser/content/tabbrowser.xml:4092:17
[task 2017-03-04T05:47:43.832063Z] 05:47:43     INFO - handleEvent@chrome://browser/content/tabbrowser.xml:4386:15
[task 2017-03-04T05:47:43.832115Z] 05:47:43     INFO - permitUnload@chrome://global/content/bindings/remote-browser.xml:357:13
[task 2017-03-04T05:47:43.832166Z] 05:47:43     INFO - _beginRemoveTab@chrome://browser/content/tabbrowser.xml:2644:46
[task 2017-03-04T05:47:43.832214Z] 05:47:43     INFO - removeTab@chrome://browser/content/tabbrowser.xml:2582:18
[task 2017-03-04T05:47:43.832274Z] 05:47:43     INFO - removeTab<@chrome://mochitests/content/browser/devtools/client/framework/test/shared-head.js:147:3
[task 2017-03-04T05:47:43.832335Z] 05:47:43     INFO - _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
[task 2017-03-04T05:47:43.832570Z] 05:47:43     INFO - TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
[task 2017-03-04T05:47:43.832673Z] 05:47:43     INFO - asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
[task 2017-03-04T05:47:43.832864Z] 05:47:43     INFO - @chrome://mochitests/content/browser/devtools/client/responsive.html/test/browser/browser_menu_item_01.js:60:9
[task 2017-03-04T05:47:43.833585Z] 05:47:43     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-04T05:47:43.834323Z] 05:47:43     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-04T05:47:43.836170Z] 05:47:43     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-04T05:47:43.836831Z] 05:47:43     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-04T05:47:43.837583Z] 05:47:43     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-04T05:47:43.839884Z] 05:47:43     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-04T05:47:43.844463Z] 05:47:43     INFO - onMessage@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/responsive.html/utils/message.js:19:5
[task 2017-03-04T05:47:43.845137Z] 05:47:43     INFO - EventListener.handleEvent*wait@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/responsive.html/utils/message.js:21:3
[task 2017-03-04T05:47:43.845748Z] 05:47:43     INFO - request@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/responsive.html/utils/message.js:52:14
[task 2017-03-04T05:47:43.851853Z] 05:47:43     INFO - ResponsiveUI.prototype.destroy<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/responsive.html/manager.js:388:13
[task 2017-03-04T05:47:43.852634Z] 05:47:43     INFO - _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
[task 2017-03-04T05:47:43.853285Z] 05:47:43     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-04T05:47:43.853912Z] 05:47:43     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-04T05:47:43.854532Z] 05:47:43     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-04T05:47:43.855138Z] 05:47:43     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-04T05:47:43.855787Z] 05:47:43     INFO - Promise.prototype.then@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:455:5
[task 2017-03-04T05:47:43.857428Z] 05:47:43     INFO - _handleResultValue@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:387:7
[task 2017-03-04T05:47:43.858039Z] 05:47:43     INFO - _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:319:13
[task 2017-03-04T05:47:43.858815Z] 05:47:43     INFO - TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
[task 2017-03-04T05:47:43.860711Z] 05:47:43     INFO - asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
[task 2017-03-04T05:47:43.861358Z] 05:47:43     INFO - exports.ResponsiveUIManager.closeIfNeeded<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/responsive.html/manager.js:114:29
[task 2017-03-04T05:47:43.864250Z] 05:47:43     INFO - _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
[task 2017-03-04T05:47:43.864914Z] 05:47:43     INFO - TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
[task 2017-03-04T05:47:43.871927Z] 05:47:43     INFO - asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
[task 2017-03-04T05:47:43.872622Z] 05:47:43     INFO - closeRDM<@chrome://mochitests/content/browser/devtools/client/responsive.html/test/browser/head.js:86:9
[task 2017-03-04T05:47:43.873300Z] 05:47:43     INFO - _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
[task 2017-03-04T05:47:43.873900Z] 05:47:43     INFO - TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
[task 2017-03-04T05:47:43.874659Z] 05:47:43     INFO - asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
[task 2017-03-04T05:47:43.876273Z] 05:47:43     INFO - @chrome://mochitests/content/browser/devtools/client/responsive.html/test/browser/browser_menu_item_01.js:55:9
[task 2017-03-04T05:47:43.876881Z] 05:47:43     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-04T05:47:43.878688Z] 05:47:43     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-04T05:47:43.879306Z] 05:47:43     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-04T05:47:43.879900Z] 05:47:43     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-04T05:47:43.880772Z] 05:47:43     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-04T05:47:43.881393Z] 05:47:43     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-04T05:47:43.882064Z] 05:47:43     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-04T05:47:43.882698Z] 05:47:43     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-04T05:47:43.883298Z] 05:47:43     INFO - _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:316:13
[task 2017-03-04T05:47:43.883897Z] 05:47:43     INFO - promise callback*_handleResultValue@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:387:7
[task 2017-03-04T05:47:43.884560Z] 05:47:43     INFO - _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:319:13
[task 2017-03-04T05:47:43.885157Z] 05:47:43     INFO - TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
[task 2017-03-04T05:47:43.886978Z] 05:47:43     INFO - asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
[task 2017-03-04T05:47:43.887604Z] 05:47:43     INFO - @chrome://mochitests/content/browser/devtools/client/responsive.html/test/browser/browser_menu_item_01.js:45:22
[task 2017-03-04T05:47:43.888233Z] 05:47:43     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-04T05:47:43.890867Z] 05:47:43     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-04T05:47:43.891495Z] 05:47:43     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-04T05:47:43.892142Z] 05:47:43     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-04T05:47:43.892779Z] 05:47:43     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-04T05:47:43.893375Z] 05:47:43     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-04T05:47:43.894955Z] 05:47:43     INFO - _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:316:13
[task 2017-03-04T05:47:43.895553Z] 05:47:43     INFO - resolve@resource://devtools/shared/deprecated-sync-thenables.js:42:40
[task 2017-03-04T05:47:43.896173Z] 05:47:43     INFO - then@resource://devtools/shared/deprecated-sync-thenables.js:22:43
[task 2017-03-04T05:47:43.896992Z] 05:47:43     INFO - resolve@resource://devtools/shared/deprecated-sync-thenables.js:74:11
[task 2017-03-04T05:47:43.898019Z] 05:47:43     INFO - listenerJson@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/client/main.js:733:9
[task 2017-03-04T05:47:43.927696Z] 05:47:43     INFO - TEST-INFO | started process screentopng
[task 2017-03-04T05:47:44.467819Z] 05:47:44     INFO - TEST-INFO | screentopng: exit 0
[task 2017-03-04T05:47:44.467945Z] 05:47:44     INFO - TEST-UNEXPECTED-FAIL | devtools/client/responsive.html/test/browser/browser_menu_item_01.js | uncaught exception - Error: Assertion failure at assert@chrome://browser/content/tabbrowser.xml:3995:25
Attachment #8843739 - Flags: review?(wmccloskey)
Attachment #8843739 - Flags: review?(wmccloskey)
Comment on attachment 8843736 [details]
Bug 1342927 - Don't fire MozTabChildNotReady from TabParent if we've already presented.

https://reviewboard.mozilla.org/r/117306/#review119376
Attachment #8843736 - Flags: review?(wmccloskey) → review+
Comment on attachment 8843737 [details]
Bug 1342927 - Don't fire MozTabChildNotReady if DocShell has become inactive or frameloader owner has dropped us.

https://reviewboard.mozilla.org/r/117308/#review119378
Attachment #8843737 - Flags: review?(wmccloskey) → review+
Comment on attachment 8843738 [details]
Bug 1342927 - Transfer pendingTabChild state when swapping docShells in tabswitcher.

https://reviewboard.mozilla.org/r/117310/#review119380
Attachment #8843738 - Flags: review?(wmccloskey) → review+
Comment on attachment 8843739 [details]
Bug 1342927 - Async tab switcher updateDisplay() should only make the requested tab blank if it's in the loading state.

https://reviewboard.mozilla.org/r/117312/#review119382
Attachment #8843739 - Flags: review?(wmccloskey) → review+
omg please stick this time.
Flags: needinfo?(mconley)
Pushed by mconley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e8148c17423b
Fire a MozTabChildNotReady event on a frameloader if force-painting a tab without a TabChild. r=billm
https://hg.mozilla.org/integration/autoland/rev/b0efb84f1c3b
Make async tab switcher show a blank tab when switching to tabs that have no TabChild yet. r=billm
https://hg.mozilla.org/integration/autoland/rev/d9c8a61dc482
Don't fire MozTabChildNotReady from TabParent if we've already presented. r=billm
https://hg.mozilla.org/integration/autoland/rev/7cca50d1e96e
Don't fire MozTabChildNotReady if DocShell has become inactive or frameloader owner has dropped us. r=billm
https://hg.mozilla.org/integration/autoland/rev/1fb3d0b0ec35
Transfer pendingTabChild state when swapping docShells in tabswitcher. r=billm
https://hg.mozilla.org/integration/autoland/rev/155331c457fd
Async tab switcher updateDisplay() should only make the requested tab blank if it's in the loading state. r=billm
https://hg.mozilla.org/integration/autoland/rev/828486abb626
Add a hidden pref to disable force painting of tabs so that browser_tabSpinnerProbe.js can pass. r=billm
You need to log in before you can comment on or make changes to this bug.