When restoring a session, "about:home" is displayed in the selected tab before the tab is restored

RESOLVED FIXED in Firefox 57

Status

()

Firefox
Session Restore
P1
normal
RESOLVED FIXED
3 years ago
2 months ago

People

(Reporter: Mark Straver, Assigned: dao)

Tracking

(Depends on: 1 bug, Blocks: 3 bugs, {perf})

Trunk
Firefox 57
Points:
---
Dependency tree / graph
Bug Flags:
qe-verify -

Firefox Tracking Flags

(firefox55 wontfix, firefox56 wontfix, firefox57 fixed)

Details

(Whiteboard: [reserve-photon-performance][bugday-20140818])

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment, 5 obsolete attachments)

(Reporter)

Description

3 years ago
User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0 (Beta/Release)
Build ID: 20140716183446

Steps to reproduce:

1. Set Firefox to "Restore windows and tabs from last time"
2. Set "Don't restore tabs until I click on them"
3. Restore a session, and click an inactive tab to restore it.


Actual results:

Firefox briefly displays a different page (usually about:home, sometimes the session restore screen or something else), then briefly displays a blank tab with the title "new tab", then restores the page from the session.


Expected results:

Restore the page immediately to the tab, do not call up a different page first, and do not call up a "new tab" page before displaying the page.

Comment 1

3 years ago
Mark,

Can you please try the troubleshooting at https://support.mozilla.org/en-US/kb/restore-previous-session#w_troubleshooting and see if that solves the problem?
Flags: needinfo?(mark)
Whiteboard: [bugday-20140818]
(Reporter)

Comment 2

3 years ago
Alex,

There is no problem actually restoring the session or tabs, and I'm in the habit of using file->exit when closing the browser to make it properly shut down. 

Tabs DO restore correctly, but not before first briefly showing about:home or a different page, then (most of the time) briefly a blank page with the tab label "New Tab", and only then displaying the proper page in the tab I clicked (all this happens automatically, but it's clearly undesirable behavior).

I've disabled classic theme restorer in case that was the issue (the only add-on I really use) but it made no difference and displays the exact same behavior.
I'm not on a slow machine either, and use fully HW accelerated graphics (Win 7).
Flags: needinfo?(mark)

Comment 3

3 years ago
¡Hola Mark!

Have you tried https://support.mozilla.org/en-US/kb/reset-firefox-easily-fix-most-problems yet?
Flags: needinfo?(mark)
(Reporter)

Comment 4

3 years ago
Did better since I didn't want to unnecessarily lose my setup, and created a test profile with the profile manager - completely blank. A little harder to make it happen because it's faster to start/restore stuff from a saved session with not having running histories behind tabs, but the problem still occurs. So, ruling out add-ons, corrupt session store, corrupt places DB or anything else in the profile.

e.g.: Opened up a bunch of tabs with different sites, including example.com, after setting the startup option to restore windows and tabs. Having a saved tab for example.com from the restored session after restarting the browser, clicking it to activate/load, it shows the about:home page briefly (less than a second but clearly visible), then goes blank, then shows example.com.
Flags: needinfo?(mark)
Hi Mark,

I have tested the mentioned issues on latest Firefox release (43.0.3) and latest Nightly (46.0a1) and I could not reproduce it. The restored tab worked properly, no different page was visible.

Firefox: 43.0.3, Build ID: 20151223140742, User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:43.0) Gecko/20100101 Firefox/43.0
Firefox: 46.0a1, Build ID: 20160105030211, User Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:46.0) Gecko/20100101 Firefox/46.0

Can you please test this on the latest Firefox release (43.0.3) or latest Nightly (46.0a1, https://nightly.mozilla.org/) and tell me if this still reproduces for you ? When doing this please use a new fresh Firefox profile, maybe also in safe mode (https://support.mozilla.org/en-US/kb/troubleshoot-and-diagnose-firefox-problems). 

Thanks,
Cosmin.
Flags: needinfo?(mark)
(Reporter)

Comment 6

2 years ago
Yes this still happens (tested in Firefox-release).
It briefly shows about:home before showing the correct page. This happens most noticeably if your active tab in the restored session is not the first tab on the tab bar, and you then click the first tab; but it also shows a very brief display of it when first starting the browser from a restored session.

I've experimented a little, and what seems to happen is that Firefox preloads whatever is set as the home page, and the brief display is whatever that is set as (default about:home, but I also tested about:preferences which also briefly displays in that case when starting the browser or restoring a tab when clicked). Any page that loads sufficiently fast (and considering it's loaded from SSD in my case, making any local or fully-cached page fast enough) will display before the actual webpage is called up from the stored session.
Flags: needinfo?(mark)

Comment 7

2 years ago
Like bug 893061 and bug 610357.
Severity: normal → minor
Component: Untriaged → Session Restore
Depends on: 610357
(Reporter)

Comment 8

2 years ago
Bug 893061 seems to be very similar in behavior -- although that is marked fixed, it was actually not fixed at all, it seems, but just postponed occurrence of the behavior (it's stated to be an optimization that can still hit this behavior if the machine is particularly slow). My machine isn't slow as one of the later comments there indicates.

Did the underlying timing of sessionrestore change that it resurfaced? Fallout from making more things async?
Still can not reproduce this issue on my end. 
Dão Gottwald is a developer that involved in both the issues mentioned above. Maybe he could share an opinion on this one. If it's the same as bug 610357, we should mark this as duplicate of it and follow the progress on that one.

Thanks,
Cosmin.
Flags: needinfo?(dao)
(Assignee)

Comment 10

2 years ago
As noted earlier, this is basically bug 893061, which can still happen depending on how fast the session file could be read relative to the first window being opened. I'm guessing we can't do much about it, except for delaying loading the homepage until the session file has definitely been read, which doesn't seem like a great idea in terms of perceived performance when the homepage does need to be loaded.
Status: UNCONFIRMED → NEW
Depends on: 893061
No longer depends on: 610357
Ever confirmed: true
Flags: needinfo?(dao)
Like it or not, we really need to rewrite all the startup of Session Restore one of these days. 

Putting it on mconley's radar, in case some miracle grants him time to spend of this.
Flags: needinfo?(mconley)
It's on my radar, but unfortunately no miracle has been granted. :/
Flags: needinfo?(mconley)
(Reporter)

Comment 13

8 months ago
I realized I duplicated this bug report in bug 1324197 which is the same behavior as described here but with extras; and it clearly doesn't matter how long after startup tabs are switched for this to occur (it always also happens on the first tab in the tab bar when switching to it) so I don't think it's a pending read from the session store file as indicated in this bug as the potential cause (the depends on is probably incorrect).

Is this related perhaps to the session history being wonky, like worked around in e.g. Bug 597315?
Depends on: 1330633
Blocks: 1330633
No longer depends on: 1330633
(Assignee)

Updated

7 months ago
Summary: Odd behavior restoring tabs from session → When restoring a session, "about:home" is displayed in the selected tab before the tab is restored
(Assignee)

Updated

7 months ago
Keywords: perf
OS: Windows 7 → All
Hardware: x86_64 → All
Version: 31 Branch → Trunk
(Assignee)

Comment 14

7 months ago
This bug is manifesting again on my Linux system with current nightly. Has there been a recent change that could have made this worse?
Severity: minor → normal
Flags: needinfo?(mdeboer)
(Assignee)

Updated

7 months ago
Blocks: 1348289
Whiteboard: [bugday-20140818] → [photon-performance][bugday-20140818]
(Assignee)

Updated

7 months ago
Duplicate of this bug: 1324197

Updated

7 months ago
Flags: qe-verify?
Priority: -- → P2
The only thing I can think of that might impact this is bug 1256472. Since the previous bug - bug 893061 - was fixed by handling things in the chrome process, I think current updates might've exposed an e10s-related regression that we simply did not port over the fix from bug 893061 over to the content process browser init flow.
Mike, I don't want to send you off to a wild-goose chase, but when you look at the patch in bug 893061 - does it seem likely that we're not preventing about:home to load in a fresh browser rigidly enough?
Flags: needinfo?(mdeboer) → needinfo?(mconley)
(Reporter)

Comment 17

7 months ago
For the record, this occurs in non-e10s for me (checked in ESR52, single process) and doesn't seem to be directly related to e10s or not.
10 tabs restored from session, firefox+profile loaded from SSD. Whatever is the home page set as is displayed for about half a second before the session restore kicks in and replaces it with the tabs -- to me it seems like loading the home page in a single tab is the default state for the browser to start up in before sessionrestore kicks in, regardless of a user's settings. This tab state is also retained for the first tab if a different tab was active in the session, and the display recurs if one switches to the first tab before that tab's contents is restored.

The root of the problem is likely this "default initial state" of the browser being a "load my home page" state, which causes active display (and network traffic if a remote page) before sessionrestore kicks in. The first tab apparently retaining this state as a stale state in its "pending" state if not the active tab in the session (and don't-load-until-selected being in use).

To solve this, we'd probably want the initial state to be "load a blank page" and then reload the home page or session pages as-appropriate once the browser initialization is complete and the session starts.
Apology for the confusion, but I meant e10s-related in the sense that we're using asynchronous message passing to kick off the restore process. This code path is used for e10s AND non-e10s.
Pretty odd.

When creating those unrestored background tabs, we tell the tabbrowser binding to send them to about:blank: http://searchfox.org/mozilla-central/rev/ce5ccb6a8ca803271c946ccb8b43b7e7d8b64e7a/browser/components/sessionstore/SessionStore.jsm#3308-3314

I can't understand why those tabs would then attempt to browse somewhere else before restoring the tab content.

I am unable to reproduce this problem myself. For the folks who can, (dao and Mark it seems), are you able to give me a sense of what's going on in ContentRestore.jsm's restoreTabContent when this problem occurs? Of these possible branches:

http://searchfox.org/mozilla-central/rev/ce5ccb6a8ca803271c946ccb8b43b7e7d8b64e7a/browser/components/sessionstore/ContentRestore.jsm#197-243

Which one is taken, and with what values?
Flags: needinfo?(mconley)
(Reporter)

Comment 20

7 months ago
I think that might be the wrong location to look at. My observation is that this behavior seems to be triggered -before- the sessionrestore process kicks in. i.e.: about:home or whatever else is loaded in the application's default startup state before session restoration kicks in. An unrestored tab might be initially about:blank, but the state before that binding occurs is not, and is the home page.

I think (feel free to correct me if I'm wrong) the following happens:
1 application starts
2 application initialized the UI, which includes tabbrowser
3 tabbrowser's initial state is (apparently) a single tab with the home page, in the case of "restore session"
4 sessionrestore is launched (asynchronously now, so the delay is more noticeable, but there would be a delay anyway)
5 if not the first tab, tab is switched to newly-added tab with about:blank, then with the restored content.
Of note, the FIRST tab is not replaced and remains the same tab, but switched to pending state, so binding to about:blank never occurs there.
6 if switching to the first tab, after that, the initial tabbrowser's tab state is still the same, with the home page content, until the restored content is loaded, once again briefly showing the home page content.

So I think the root of the problem here is point 3. This has been the case since somewhere in the 20's range of Firefox versions, afaict, just not very noticeable with fast enough startup of session restore. I do not know where to look for that part of the startup sequence of the browser; not familiar enough with the code.

I hope this observation helps.
(In reply to Mark Straver from comment #20)
> 
> I hope this observation helps.

Ah, yes, that is helpful.

In the event that we're "re-using" a tab, http://searchfox.org/mozilla-central/rev/ce5ccb6a8ca803271c946ccb8b43b7e7d8b64e7a/browser/components/sessionstore/SessionStore.jsm#3308-3314 doesn't end up sending it anywhere. So I believe if we restore onto a window with a tab that's already pointed somewhere, and that tab is going to be in the background, I think that means that we just keep that loaded tab hanging around until selection, at which time we'll restore the tab content over top of it - but by that time, the jig's up, and we had the chance of sending the frame of the original content to the compositor.

I think that at least part of this should be mitigated by the fix in bug 1351677, where instead of switching to the selected tab on restoration, we _move_ the originally selected tab to the desired position and load its content in there. But maybe there are cases there I didn't consider.

Is any of this useful, mikedeboer?
(Assignee)

Comment 22

7 months ago
(In reply to Mike Conley (:mconley) - PTO on April 28th. from comment #21)
> In the event that we're "re-using" a tab,

This seems to be a misguided perf optimization. Perhaps we should just stop doing this?
(Assignee)

Comment 23

7 months ago
(In reply to Dão Gottwald [::dao] from comment #22)
> (In reply to Mike Conley (:mconley) - PTO on April 28th. from comment #21)
> > In the event that we're "re-using" a tab,
> 
> This seems to be a misguided perf optimization. Perhaps we should just stop
> doing this?

I'll give this a shot.
Assignee: nobody → dao+bmo
Status: NEW → ASSIGNED
Priority: P2 → P1
(In reply to Dão Gottwald [::dao] from comment #23)
> I'll give this a shot.

Cool. What you're going to try is to removeTab instead of reuse?
(Assignee)

Comment 25

7 months ago
(In reply to Mike de Boer [:mikedeboer] from comment #24)
> (In reply to Dão Gottwald [::dao] from comment #23)
> > I'll give this a shot.
> 
> Cool. What you're going to try is to removeTab instead of reuse?

yep
(Assignee)

Comment 26

7 months ago
Created attachment 8862940 [details] [diff] [review]
WIP patch

there are intermittent failures in browser_615394-SSWindowState_events.js
(Assignee)

Comment 27

7 months ago
(In reply to Dão Gottwald [::dao] from comment #26)
> there are intermittent failures in browser_615394-SSWindowState_events.js

https://treeherder.mozilla.org/#/jobs?repo=try&revision=e24ba2480d840ba7f31759b6170100a7e7275137
(Assignee)

Updated

7 months ago
Depends on: 1361428
(Assignee)

Comment 28

7 months ago
(In reply to Dão Gottwald [::dao] from comment #22)
> (In reply to Mike Conley (:mconley) - PTO on April 28th. from comment #21)
> > In the event that we're "re-using" a tab,
> 
> This seems to be a misguided perf optimization. Perhaps we should just stop
> doing this?

So much of the complexity around reusing tabs was added recently in bug 1351677. As mconley noted in bug 1351677 comment 11, lazy browsers basically solved that bug, and in retrospect I don't think it holds that bug 1351677's changes (and more generally, reusing tabs at all, which we've been doing for much longer) are a worthwhile or even useful optimization on their own.
(Assignee)

Updated

7 months ago
Attachment #8862940 - Attachment is obsolete: true
Comment hidden (mozreview-request)
(Assignee)

Comment 30

7 months ago
(In reply to Dão Gottwald [::dao] from comment #26)
> Created attachment 8862940 [details] [diff] [review]
> WIP patch
> 
> there are intermittent failures in browser_615394-SSWindowState_events.js

Bug 1361428 seems to have solved this. I made no other changes to my patch.
(Assignee)

Comment 31

7 months ago
mozreview-review
Comment on attachment 8864038 [details]
Bug 1054740 - When a session should be restored, don't load the homepage before the session file has been read.

https://reviewboard.mozilla.org/r/135762/#review138778

::: browser/components/sessionstore/SessionStore.jsm
(Diff revision 1)
>          tabbrowser.showTab(tabs[t]);
>          numVisibleTabs++;
>        }
> -
> -      if (!!winData.tabs[t].muted != tabs[t].linkedBrowser.audioMuted) {
> -        tabs[t].toggleMuteAudio(winData.tabs[t].muteReason);

Note that toggleMuteAudio is called again later in restoreTab (and should probably move to restoreTabContent, I think), so I removed the redundancy while I was touching this loop.
Comment on attachment 8864038 [details]
Bug 1054740 - When a session should be restored, don't load the homepage before the session file has been read.

https://reviewboard.mozilla.org/r/135762/#review138818

Well, I can't say that I spotted something alarming... but that doesn't mean we won't have any follow-up bug reports ;-) There are just, well, many edge cases that I hope the tests that have accumulated over the years are already covering.
So, r=me with a green try run!

Thanks for taking this on and also for splitting up the test that we're turning orange here!

::: browser/components/sessionstore/SessionStore.jsm
(Diff revision 1)
>          tabbrowser.showTab(tabs[t]);
>          numVisibleTabs++;
>        }
> -
> -      if (!!winData.tabs[t].muted != tabs[t].linkedBrowser.audioMuted) {
> -        tabs[t].toggleMuteAudio(winData.tabs[t].muteReason);

Agreed. The whole mute-audio and block-media implementation is a bit worrysome on the browser side. I'm taking a thorough look at it with Alastor in bug 1347791.
Attachment #8864038 - Flags: review?(mdeboer) → review+
(Assignee)

Comment 33

7 months ago
Green try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=415881bcd6ebe9f500fbb1696e8ed71e29b1a82b

Comment 34

7 months ago
Pushed by dgottwald@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/43f195f28f6a
Stop reusing tabs when restoring windows since at this point it's counterproductive rather than a useful optimization. r=mikedeboer
Backed out for failing test_quit_restart.py TestQuitRestart.test_in_app_restart_with_callback in Mn-e10s on OSX 10.10 opt:

https://hg.mozilla.org/integration/autoland/rev/cba7bc0b2e18a24ea40719bc1bcf2b26701de6ee

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=43f195f28f6a2efc5ab58b5b371b8b905b77cd8b&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=96303489&repo=autoland

09:33:57     INFO - TEST-START | test_quit_restart.py TestQuitRestart.test_in_app_restart_with_callback
09:33:57     INFO - TEST-UNEXPECTED-ERROR | test_quit_restart.py TestQuitRestart.test_in_app_restart_with_callback | NoSuchWindowException: No such content frame; perhaps the listener was not registered?
09:33:57     INFO - stacktrace:
09:33:57     INFO - 	WebDriverError@chrome://marionette/content/error.js:212:5
09:33:57     INFO - 	NoSuchWindowError@chrome://marionette/content/error.js:427:5
09:33:57     INFO - 	GeckoDriver.prototype.broadcastDelayedAsyncMessage_/<@chrome://marionette/content/driver.js:287:13
09:33:57     INFO - 	executeWhenReady@chrome://marionette/content/browser.js:382:7
09:33:57     INFO - 	GeckoDriver.prototype.broadcastDelayedAsyncMessage_@chrome://marionette/content/driver.js:282:3
09:33:57     INFO - 	GeckoDriver.prototype.sendAsync@chrome://marionette/content/driver.js:275:5
09:33:57     INFO - 	send/<@chrome://marionette/content/proxy.js:138:7
09:33:57     INFO - 	send@chrome://marionette/content/proxy.js:105:12
09:33:57     INFO - 	get/<@chrome://marionette/content/proxy.js:24:25
09:33:57     INFO - 	GeckoDriver.prototype.setTestName@chrome://marionette/content/driver.js:2396:9
09:33:57     INFO - 	TaskImpl_run@resource://gre/modules/Task.jsm:319:42
09:33:57     INFO - 	TaskImpl@resource://gre/modules/Task.jsm:277:3
09:33:57     INFO - 	asyncFunction@resource://gre/modules/Task.jsm:252:14
09:33:57     INFO - 	Task_spawn@resource://gre/modules/Task.jsm:166:12
09:33:57     INFO - 	TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
09:33:57     INFO - 	TaskImpl_run@resource://gre/modules/Task.jsm:327:15
09:33:57     INFO - 	TaskImpl@resource://gre/modules/Task.jsm:277:3
09:33:57     INFO - 	asyncFunction@resource://gre/modules/Task.jsm:252:14
09:33:57     INFO - 	Task_spawn@resource://gre/modules/Task.jsm:166:12
09:33:57     INFO - 	execute@chrome://marionette/content/server.js:499:15
09:33:57     INFO - 	onPacket@chrome://marionette/content/server.js:470:7
09:33:57     INFO - 	_onJSONObjectReady/<@chrome://marionette/content/transport.js:480:9
09:33:57     INFO - Traceback (most recent call last):
09:33:57     INFO -   File "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 147, in run
09:33:57     INFO -     self.setUp()
09:33:57     INFO -   File "/builds/slave/test/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 70, in setUp
09:33:57     INFO -     MarionetteTestCase.setUp(self)
09:33:57     INFO -   File "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 469, in setUp
09:33:57     INFO -     self.marionette.test_name = self.test_name
09:33:57     INFO -   File "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1338, in test_name
09:33:57     INFO -     self._send_message("setTestName", {"value": test_name})
09:33:57     INFO -   File "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 23, in _
09:33:57     INFO -     return func(*args, **kwargs)
09:33:57     INFO -   File "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 735, in _send_message
09:33:57     INFO -     self._handle_error(err)
09:33:57     INFO -   File "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 768, in _handle_error
09:33:57     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
Flags: needinfo?(dao+bmo)
(Assignee)

Comment 36

7 months ago
(In reply to Sebastian Hengst [:aryx][:archaeopteryx] (needinfo on intermittent or backout) from comment #35)
> Backed out for failing test_quit_restart.py
> TestQuitRestart.test_in_app_restart_with_callback in Mn-e10s on OSX 10.10
> opt:
> 
> https://hg.mozilla.org/integration/autoland/rev/
> cba7bc0b2e18a24ea40719bc1bcf2b26701de6ee
> 
> Push with failures:
> https://treeherder.mozilla.org/#/
> jobs?repo=autoland&revision=43f195f28f6a2efc5ab58b5b371b8b905b77cd8b&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=96303489&repo=autoland
> 
> 09:33:57     INFO - TEST-START | test_quit_restart.py
> TestQuitRestart.test_in_app_restart_with_callback
> 09:33:57     INFO - TEST-UNEXPECTED-ERROR | test_quit_restart.py
> TestQuitRestart.test_in_app_restart_with_callback | NoSuchWindowException:
> No such content frame; perhaps the listener was not registered?
> 09:33:57     INFO - stacktrace:
> 09:33:57     INFO - 
> WebDriverError@chrome://marionette/content/error.js:212:5
> 09:33:57     INFO - 
> NoSuchWindowError@chrome://marionette/content/error.js:427:5
> 09:33:57     INFO - 
> GeckoDriver.prototype.broadcastDelayedAsyncMessage_/<@chrome://marionette/
> content/driver.js:287:13
> 09:33:57     INFO - 
> executeWhenReady@chrome://marionette/content/browser.js:382:7
> 09:33:57     INFO - 
> GeckoDriver.prototype.broadcastDelayedAsyncMessage_@chrome://marionette/
> content/driver.js:282:3
> 09:33:57     INFO - 
> GeckoDriver.prototype.sendAsync@chrome://marionette/content/driver.js:275:5
> 09:33:57     INFO - 	send/<@chrome://marionette/content/proxy.js:138:7
> 09:33:57     INFO - 	send@chrome://marionette/content/proxy.js:105:12
> 09:33:57     INFO - 	get/<@chrome://marionette/content/proxy.js:24:25
> 09:33:57     INFO - 
> GeckoDriver.prototype.setTestName@chrome://marionette/content/driver.js:2396:
> 9
> 09:33:57     INFO - 	TaskImpl_run@resource://gre/modules/Task.jsm:319:42
> 09:33:57     INFO - 	TaskImpl@resource://gre/modules/Task.jsm:277:3
> 09:33:57     INFO - 	asyncFunction@resource://gre/modules/Task.jsm:252:14
> 09:33:57     INFO - 	Task_spawn@resource://gre/modules/Task.jsm:166:12
> 09:33:57     INFO - 
> TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
> 09:33:57     INFO - 	TaskImpl_run@resource://gre/modules/Task.jsm:327:15
> 09:33:57     INFO - 	TaskImpl@resource://gre/modules/Task.jsm:277:3
> 09:33:57     INFO - 	asyncFunction@resource://gre/modules/Task.jsm:252:14
> 09:33:57     INFO - 	Task_spawn@resource://gre/modules/Task.jsm:166:12
> 09:33:57     INFO - 	execute@chrome://marionette/content/server.js:499:15
> 09:33:57     INFO - 	onPacket@chrome://marionette/content/server.js:470:7
> 09:33:57     INFO - 
> _onJSONObjectReady/<@chrome://marionette/content/transport.js:480:9
> 09:33:57     INFO - Traceback (most recent call last):
> 09:33:57     INFO -   File
> "/builds/slave/test/build/venv/lib/python2.7/site-packages/
> marionette_harness/marionette_test/testcases.py", line 147, in run
> 09:33:57     INFO -     self.setUp()
> 09:33:57     INFO -   File
> "/builds/slave/test/build/tests/marionette/tests/testing/marionette/harness/
> marionette_harness/tests/unit/test_quit_restart.py", line 70, in setUp
> 09:33:57     INFO -     MarionetteTestCase.setUp(self)
> 09:33:57     INFO -   File
> "/builds/slave/test/build/venv/lib/python2.7/site-packages/
> marionette_harness/marionette_test/testcases.py", line 469, in setUp
> 09:33:57     INFO -     self.marionette.test_name = self.test_name
> 09:33:57     INFO -   File
> "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_driver/
> marionette.py", line 1338, in test_name
> 09:33:57     INFO -     self._send_message("setTestName", {"value":
> test_name})
> 09:33:57     INFO -   File
> "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_driver/
> decorators.py", line 23, in _
> 09:33:57     INFO -     return func(*args, **kwargs)
> 09:33:57     INFO -   File
> "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_driver/
> marionette.py", line 735, in _send_message
> 09:33:57     INFO -     self._handle_error(err)
> 09:33:57     INFO -   File
> "/builds/slave/test/build/venv/lib/python2.7/site-packages/marionette_driver/
> marionette.py", line 768, in _handle_error
> 09:33:57     INFO -     raise errors.lookup(error)(message,
> stacktrace=stacktrace)

ato, can you make sense of this failure?
Flags: needinfo?(dao+bmo) → needinfo?(ato)
Judging from the raw Gecko log (http://mozilla-releng-blobs.s3.amazonaws.com/blobs/autoland/sha512/c0c9f34a4083a17782e2d53583e13fc7871003f4aeaa656b6ab0db4d454c370b9b43b7fc6b17aa60a53684a417488a8976fea1711fc872c755cc40688450a469), it is actually TestQuitRestart.test_in_app_restart that is failing when it fails to log that the test has ended.

This test sends a command to ask Firefox to restart, which ends up calling Services.startup.quit(eRestart):

> 1493829233687	Marionette	TRACE	3 -> [0,20,"quitApplication",{"flags":["eRestart","eAttemptQuit"]}]

Firefox is restarted and a few more Marionette commands are executed without error, before it fails when calling a command that interacts with the current top-level browsing context:

> …
> 1493829237307	Marionette	TRACE	2 -> [0,12,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"testcases.py","script":"log('TEST-END: /builds/slave/test/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py:test_in_app_restart')","sandbox":"simpletest","line":487}]
> 1493829237309	Marionette	TRACE	2 <- [1,12,{"error":"no such window","message":"No such content frame; perhaps the listener was not registered?","stacktrace":…},null]

Expanded, the stack trace reads:

> WebDriverError@chrome://marionette/content/error.js:212:5
> NoSuchWindowError@chrome://marionette/content/error.js:427:5
> GeckoDriver.prototype.broadcastDelayedAsyncMessage_/<@chrome://marionette/content/driver.js:287:13
> executeWhenReady@chrome://marionette/content/browser.js:382:7
> GeckoDriver.prototype.broadcastDelayedAsyncMessage_@chrome://marionette/content/driver.js:282:3
> GeckoDriver.prototype.sendAsync@chrome://marionette/content/driver.js:275:5
> send/<@chrome://marionette/content/proxy.js:138:7
> send@chrome://marionette/content/proxy.js:105:12
> get/<@chrome://marionette/content/proxy.js:24:25
> GeckoDriver.prototype.execute_@chrome://marionette/content/driver.js:891:16
> GeckoDriver.prototype.executeScript@chrome://marionette/content/driver.js:803:27
> TaskImpl_run@resource://gre/modules/Task.jsm:319:42
> TaskImpl@resource://gre/modules/Task.jsm:277:3
> asyncFunction@resource://gre/modules/Task.jsm:252:14
> Task_spawn@resource://gre/modules/Task.jsm:166:12
> TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
> TaskImpl_run@resource://gre/modules/Task.jsm:327:15
> TaskImpl@resource://gre/modules/Task.jsm:277:3
> asyncFunction@resource://gre/modules/Task.jsm:252:14
> Task_spawn@resource://gre/modules/Task.jsm:166:12
> execute@chrome://marionette/content/server.js:499:15
> onPacket@chrome://marionette/content/server.js:470:7
> _onJSONObjectReady/<@chrome://marionette/content/transport.js:480:9

GeckoDriver.prototype.broadcastDelayedAsyncMessage_ calls this.mm.broadcastAsyncMessage(target, payload), where target is this.curBrowser.curFrameId.  My guess is that Marionette is failing to register a frame script (and the frame script consequently registering itself with Marionette) after the call to Services.startup.quit(eRestart).

It’s not clear to me exactly what this patch changes since I’m not familiar with that part of Firefox, but it’s likely this is an issue with code in testing/marionette/driver.js’s whenBrowserStarted, registerBrowser, registerPromise, et al.
Flags: needinfo?(ato)
(Assignee)

Comment 38

7 months ago
(In reply to Andreas Tolfsen ‹:ato› from comment #37)
> GeckoDriver.prototype.broadcastDelayedAsyncMessage_ calls
> this.mm.broadcastAsyncMessage(target, payload), where target is
> this.curBrowser.curFrameId.  My guess is that Marionette is failing to
> register a frame script (and the frame script consequently registering
> itself with Marionette) after the call to Services.startup.quit(eRestart).

The "No such content frame; perhaps the listener was not registered?" error suggests that we don't even reach the broadcastAsyncMessage call, right? I.e. it's failing the (this.curBrowser.curFrameId) check. Why would this happen? I don't see where curFrameId is being set.

> It’s not clear to me exactly what this patch changes since I’m not familiar
> with that part of Firefox, but it’s likely this is an issue with code in
> testing/marionette/driver.js’s whenBrowserStarted, registerBrowser,
> registerPromise, et al.

The patch makes sessionstore not re-use the initial browser.

E.g. without this patch, when restoring a session with three 3 tabs, sessionstore would roughly:
- add 2 tabs
- use the initial tab that would normally load about:home, and restore content into that browser

With this patch:
- add 3 tabs
- close the initial tab that would normally load about:home
Flags: needinfo?(ato)
this.curBrowser.curFrameId is being set in http://searchfox.org/mozilla-central/rev/abe68d5dad139e376d5521ca1d4b7892e1e7f1ba/testing/marionette/browser.js#320 when the frame script calls back to chrome in http://searchfox.org/mozilla-central/rev/abe68d5dad139e376d5521ca1d4b7892e1e7f1ba/testing/marionette/driver.js#525.

If it is the case that curFrameId is not set or wrong, then the content frame script
never gets loaded.  Are you seeing a log line such as "Loaded listener.js" when you
run the test with the debug output flags?

Relevant flags to redirect the Gecko log to stdout and crank up the verbosity:

    % ./mach marionette-test testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py --gecko-log -vv

If you do see this message, it means testing/marionette/listener.js was correctly
loaded in.  It does not, however, guarantee that the frame script registered correctly
with chrome (driver.js/browser.js).

> The "No such content frame; perhaps the listener was not registered?" error
> suggests that we don't even reach the broadcastAsyncMessage call, right?

Not necessarily.  The try…catch wraps both the call to this.curBrowser.curFrameId
_and_ the call to braodcastAsyncMessage and discards the original error.  But yes,
it could be that the curFrameId getter in testing/marionette/browser.js fails.
Flags: needinfo?(ato)
(Assignee)

Comment 40

7 months ago
(In reply to Andreas Tolfsen ‹:ato› from comment #39)
> If it is the case that curFrameId is not set or wrong, then the content
> frame script
> never gets loaded.  Are you seeing a log line such as "Loaded listener.js"
> when you
> run the test with the debug output flags?

I'm on Linux where the test passes just fine.

> > The "No such content frame; perhaps the listener was not registered?" error
> > suggests that we don't even reach the broadcastAsyncMessage call, right?
> 
> Not necessarily.  The try…catch wraps both the call to
> this.curBrowser.curFrameId
> _and_ the call to braodcastAsyncMessage and discards the original error. 
> But yes,
> it could be that the curFrameId getter in testing/marionette/browser.js
> fails.

I'm not seeing any try..catch wrapping these things in broadcastDelayedAsyncMessage_.

Anyway... I think my patch isn't really breaking anything here from a user's perspective, but the marionette framework is brittle and needs an expert in that area to dig deeper. I think I'll file a followup bug on that and land with the test disabled on Mac.
(In reply to Dão Gottwald [::dao] from comment #38)
> With this patch:
> - add 3 tabs
> - close the initial tab that would normally load about:home

The removal of the initial tab is the problem here. And it's most likely a race condition which could affect not only this specific test, but all restart related tests as run by Marionette when sessionstore is enabled - in this case it happens because of the crash. Then we try to restore the last open tabs after a restart.
(Assignee)

Comment 42

7 months ago
(In reply to Henrik Skupin (:whimboo) from comment #41)
> (In reply to Dão Gottwald [::dao] from comment #38)
> > With this patch:
> > - add 3 tabs
> > - close the initial tab that would normally load about:home
> 
> The removal of the initial tab is the problem here.

Sure, except that that's not a problem by itself. From what I can tell the actual problem is buried somewhere in marionette's intertwined guts.

> And it's most likely a
> race condition which could affect not only this specific test, but all
> restart related tests as run by Marionette when sessionstore is enabled

Yep. That it's passing on Mac debug but failing on opt suggests that there's a race condition which could potentially manifest in other marionette tests and on other platforms.
Well, the problem is that Marionette gets initialized when the `sessionstore-windows-restored` observer notification is received. At this time we also setup the initial browser Marionette interacts with, which also loads the framescript in the content browser of the initial tab.

I assume that your code also runs after this notification? So what basically happens is that it removes the currently selected tab/browser Marionette interacts with. So a next command which gets run in the framescript scope, will fail because the tab doesn't exist anymore.

There is nothing we can do to prevent this in Marionette, given that the Webdriver spec specifies that a test has to explicitly switch to another tab. And here it is not known to the test that the initial tab gets removed.

So I had a look at the test file and we unfortunately use `browser.startup.page` set to `3`, to verify that the restart was successful, and the pref has been reset afterward. But that won't happen for in-app restarts, and as such the preference value will remain and causes sessionrestore to be active.

So please mark the test_quit_restart.py file as skipped for all platforms and file a follow-up bug for Marionette. I will get this fixed/changed tomorrow.
(Assignee)

Comment 44

7 months ago
(In reply to Henrik Skupin (:whimboo) from comment #43)
> Well, the problem is that Marionette gets initialized when the
> `sessionstore-windows-restored` observer notification is received. At this
> time we also setup the initial browser Marionette interacts with, which also
> loads the framescript in the content browser of the initial tab.
> 
> I assume that your code also runs after this notification?

No, SessionStore.jsm sets up tabs before sending that notification.

> So please mark the test_quit_restart.py file as skipped for all platforms
> and file a follow-up bug for Marionette. I will get this fixed/changed
> tomorrow.

Okay.
(Assignee)

Updated

7 months ago
Depends on: 1361837
Comment hidden (mozreview-request)

Comment 46

7 months ago
Pushed by dgottwald@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/db9f3b377504
Stop reusing tabs when restoring windows since at this point it's counterproductive rather than a useful optimization. r=mikedeboer
Backed out for failing Marionette's test_prefs.py TestPreferences.test_clear_pref, at least on Linux in non-e10s mode:

https://hg.mozilla.org/integration/autoland/rev/f70b79458a13029f08114f66923cb1c8ee7cdd2d

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=db9f3b3775046151f27cf0d668d34786b0034c56&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=96380778&repo=autoland

[task 2017-05-03T20:52:53.233507Z] 20:52:53     INFO - TEST-START | test_prefs.py TestPreferences.test_clear_pref
[task 2017-05-03T20:52:53.392191Z] 20:52:53     INFO - TEST-UNEXPECTED-FAIL | test_prefs.py TestPreferences.test_clear_pref | AssertionError: True is not None
[task 2017-05-03T20:52:53.392282Z] 20:52:53     INFO - Traceback (most recent call last):
[task 2017-05-03T20:52:53.392359Z] 20:52:53     INFO -   File "/home/worker/workspace/build/venv/local/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 166, in run
[task 2017-05-03T20:52:53.393367Z] 20:52:53     INFO -     testMethod()
[task 2017-05-03T20:52:53.394011Z] 20:52:53     INFO -   File "/home/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_prefs.py", line 24, in test_clear_pref
[task 2017-05-03T20:52:53.394605Z] 20:52:53     INFO -     self.assertIsNone(self.marionette.get_pref(self.prefs["bool"]))
Flags: needinfo?(dao+bmo)
Comment hidden (mozreview-request)
(Assignee)

Comment 49

7 months ago
(In reply to Sebastian Hengst [:aryx][:archaeopteryx] (needinfo on intermittent or backout) from comment #47)
> Backed out for failing Marionette's test_prefs.py
> TestPreferences.test_clear_pref, at least on Linux in non-e10s mode:

Marionette </3

My latest patch update should avoid the above problem by disabling specific parts of test_quit_restart.py rather than the whole test. Somehow disabling the test makes test_prefs.py fail, which seems completely bogus.
Flags: needinfo?(dao+bmo)
Sorry, but I haven't had the time today to spend much of time for this issue. But I run a build with your changes locally a couple of times on OS X. Sadly it didn't fail. I will have a look when the code landed and got merged to m-c.

Comment 51

7 months ago
Pushed by dgottwald@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/47612d95b177
Stop reusing tabs when restoring windows since at this point it's counterproductive rather than a useful optimization. r=mikedeboer

Comment 52

7 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/47612d95b177
Status: ASSIGNED → RESOLVED
Last Resolved: 7 months ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
(Assignee)

Updated

7 months ago
Blocks: 1362595

Updated

7 months ago
Iteration: --- → 55.5 - May 15
(Reporter)

Comment 53

7 months ago
Interesting approach, but does this actually prevent the issue of the initial state of the browser loading the home page (and potentially causing network connections before the load is halted)?

After all, in browser.js, _getUriToLoad calls sessionStartup.willOverrideHomepage, and only blocks the DefaultArgs situation load if that returns true. But willOverrideHomepage() in nsSessionStartup.js will simply return false if the session file hasn't been read yet (and thus doesn't block the load). I think that is the root cause of this problem, not how the actual tab restore handling juggles tabs...
(Assignee)

Comment 54

7 months ago
(In reply to Mark Straver from comment #53)
> Interesting approach, but does this actually prevent the issue of the
> initial state of the browser loading the home page (and potentially causing
> network connections before the load is halted)?

No, it doesn't. As before in bug 893061, we're attacking the issue from one specific angle, but as you say between the initial window being opened and the session file being read there's still a window of opportunity for about:home to be loaded and displayed. We'll probably need a third bug for this remaining case.
(Assignee)

Updated

7 months ago
Blocks: 1362755
(Assignee)

Comment 55

7 months ago
(In reply to Dão Gottwald [::dao] from comment #54)
> (In reply to Mark Straver from comment #53)
> > Interesting approach, but does this actually prevent the issue of the
> > initial state of the browser loading the home page (and potentially causing
> > network connections before the load is halted)?
> 
> No, it doesn't. As before in bug 893061, we're attacking the issue from one
> specific angle, but as you say between the initial window being opened and
> the session file being read there's still a window of opportunity for
> about:home to be loaded and displayed. We'll probably need a third bug for
> this remaining case.

Filed bug 1362755.
Depends on: 1362866
Depends on: 1362502
Depends on: 1362917
Depends on: 1362799
Depends on: 1363087
Depends on: 1363368
No longer depends on: 1363368
No longer blocks: 1348289
Blocks: 1348289

Updated

6 months ago
Flags: qe-verify? → qe-verify+
QA Contact: adrian.florinescu

Comment 56

6 months ago
It appears as though this bug may have contributed to a sudden change in the Telemetry probe FX_SESSION_RESTORE_RESTORE_WINDOW_MS[1] which seems to have occurred in Nightly 20170506[2][3].

It seems as though it got rather slower. And it seems from [2] that it's undoing a previous improvement in this arena.

Is this actually a regression? Is this intentional? Is it expected?

Is this probe measuring something useful?

[1]: http://alerts.telemetry.mozilla.org/index.html#/detectors/1/metrics/750/alerts/?from=2017-05-06&to=2017-05-06
[2]: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=0b255199db9d6a6f189b89b7906f99155bde3726&tochange=37a5b7f6f101df2eb292b1b6baaf1540c9920e20
[3]: https://mzl.la/2rnqPjP
Flags: needinfo?(dao+bmo)
(Assignee)

Comment 57

6 months ago
(In reply to Chris H-C :chutten from comment #56)
> It appears as though this bug may have contributed to a sudden change in the
> Telemetry probe FX_SESSION_RESTORE_RESTORE_WINDOW_MS[1] which seems to have
> occurred in Nightly 20170506[2][3].

filed bug 1365541
Depends on: 1365541
No longer depends on: 1362502, 1362799, 1362917, 1363087
Flags: needinfo?(dao+bmo)
All the test failures for Marionette are still regressions from this change, and as such should be kept on the dependency list.
(Assignee)

Comment 59

6 months ago
They're already tracked as part of bug 1361837 and just clutter the dependency list here, needlessly making it harder for me to actually work with the dependency list.
No longer depends on: 1362502, 1362799, 1362917, 1363087
Depends on: 1371884
This was reverted in bug 1371884, so qe-verify-.
Flags: qe-verify+ → qe-verify-

Updated

4 months ago
QA Contact: adrian.florinescu
(Assignee)

Updated

3 months ago
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(Assignee)

Updated

3 months ago
No longer blocks: 1362755
Duplicate of this bug: 1362755
(Assignee)

Updated

3 months ago
Attachment #8864038 - Attachment is obsolete: true
(Assignee)

Updated

3 months ago
Blocks: 1388628
No longer depends on: 1365541

Updated

3 months ago
Iteration: 55.5 - May 15 → ---

Comment 62

3 months ago
Is this broken (and fixed) in versions 56 and 57? Unclear from notes up top (Trunk). Thanks.
(Assignee)

Updated

3 months ago
Depends on: 1389525
(Assignee)

Comment 63

3 months ago
(In reply to Worcester12345 from comment #62)
> Is this broken (and fixed) in versions 56 and 57?

It's broken, not fixed.
status-firefox55: fixed → ---
(Assignee)

Comment 64

3 months ago
Created attachment 8896437 [details] [diff] [review]
WIP patch
(Assignee)

Comment 65

3 months ago
https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=7145657b8d5d9cf0cb4b0889c086091bb2323443&newProject=try&newRevision=d41079d2e160b56b7da54fccee6f6455173a0de7&framework=1&showOnlyConfident=1
(Assignee)

Comment 66

3 months ago
https://treeherder.mozilla.org/#/jobs?repo=try&revision=d41079d2e160b56b7da54fccee6f6455173a0de7
(Assignee)

Comment 67

3 months ago
Created attachment 8897493 [details] [diff] [review]
WIP patch

Might be a good idea to start looking at this patch while I try to make a bunch of tests happy.
Attachment #8896437 - Attachment is obsolete: true
Attachment #8897493 - Flags: feedback?(mdeboer)
(Assignee)

Comment 68

3 months ago
https://treeherder.mozilla.org/#/jobs?repo=try&revision=191410b960a43bc717d5fecb4390f1329d160712&selectedJob=123608589

I can't figure out what browser_windowopen_reflows.js wants me to update the stack to. Mike?
(Assignee)

Comment 69

3 months ago
(In reply to Dão Gottwald [::dao] from comment #68)
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=191410b960a43bc717d5fecb4390f1329d160712&selectedJob=1
> 23608589
> 
> I can't figure out what browser_windowopen_reflows.js wants me to update the
> stack to. Mike?
Flags: needinfo?(mconley)
(Assignee)

Comment 70

3 months ago
Created attachment 8897905 [details] [diff] [review]
WIP patch
Attachment #8897493 - Attachment is obsolete: true
Attachment #8897493 - Flags: feedback?(mdeboer)
Attachment #8897905 - Flags: feedback?(mdeboer)
(In reply to Dão Gottwald [::dao] from comment #68)
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=191410b960a43bc717d5fecb4390f1329d160712&selectedJob=1
> 23608589
> 
> I can't figure out what browser_windowopen_reflows.js wants me to update the
> stack to. Mike?

Here's the relevant part of the log:

15:22:19    ERROR -  750 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_windowopen_reflows.js | unexpected uninterruptible reflow
15:22:19     INFO -  [
15:22:19     INFO -  	"select@chrome://global/content/bindings/textbox.xml:115:11",
15:22:19     INFO -  	"focusAndSelectUrlBar@chrome://browser/content/browser.js:2285:5",
15:22:19     INFO -  	"_handleURIToLoad/<@chrome://browser/content/browser.js:1699:11",
15:22:19     INFO -  	"promise callback*_handleURIToLoad@chrome://browser/content/browser.js:1697:5",
15:22:19     INFO -  	"_delayedStartup@chrome://browser/content/browser.js:1442:5",
15:22:19     INFO -  	"EventListener.handleEvent*onLoad@chrome://browser/content/browser.js:1387:5",
15:22:19     INFO -  	"onload@chrome://browser/content/browser.xul:1:1",
15:22:19     INFO -  	""
15:22:19     INFO -  ]
15:22:19     INFO -   - false == true - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: reflow :: line 104
15:22:19     INFO -  Stack trace:
15:22:19     INFO -  chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:reflow:104
15:22:19     INFO -  chrome://global/content/bindings/textbox.xml:select:115
15:22:19     INFO -  chrome://browser/content/browser.js:focusAndSelectUrlBar:2285
15:22:19     INFO -  chrome://browser/content/browser.js:_handleURIToLoad/<:1699
15:22:19     INFO -  Not taking screenshot here: see the one that was previously logged
15:22:19    ERROR -  751 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_windowopen_reflows.js | Unused expected reflow: [
15:22:19     INFO -  	"select@chrome://global/content/bindings/textbox.xml",
15:22:19     INFO -  	"focusAndSelectUrlBar@chrome://browser/content/browser.js",
15:22:19     INFO -  	"_handleURIToLoad@chrome://browser/content/browser.js",
15:22:19     INFO -  	"promise callback*_handleURIToLoad@chrome://browser/content/browser.js",
15:22:19     INFO -  	"_delayedStartup@chrome://browser/content/browser.js",
15:22:19     INFO -  	"EventListener.handleEvent*onLoad@chrome://browser/content/browser.js",
15:22:19     INFO -  	"onload@chrome://browser/content/browser.xul"
15:22:19     INFO -  ]

The match is failing on _handleURIToLoad/< vs __handleURIToLoad.

I'm not 100% certain why the function signature for those two frames differ like that, but if I had to guess, I'd say that this is because focusAndSelectUrlBar is being called from _handleURIToLoad from a Promise callback. I suspect this will actually break in non-Nightly because we don't have async stacks being reported except on Nightly (see bug 1386246, which fixed a similar problem).

So what I'd suggest is to avoid the async stack problem entirely by changing the signature to:

stack: [
  "select@chrome://global/content/bindings/textbox.xml",
  "focusAndSelectUrlBar@chrome://browser/content/browser.js",
  /* Feel free to put extra commentary here about the reflow being kicked
     off of the Promise callback inside _handleURIToLoad, etc */
]
Flags: needinfo?(mconley)
(Assignee)

Comment 72

3 months ago
Created attachment 8898917 [details] [diff] [review]
WIP patch

(In reply to Mike Conley (:mconley) from comment #71)
> So what I'd suggest is to avoid the async stack problem entirely by changing
> the signature to:
> 
> stack: [
>   "select@chrome://global/content/bindings/textbox.xml",
>   "focusAndSelectUrlBar@chrome://browser/content/browser.js",
>   /* Feel free to put extra commentary here about the reflow being kicked
>      off of the Promise callback inside _handleURIToLoad, etc */
> ]

Works. Thanks!

The only remaining problems appear to be accessible/tests/mochitest/hittest/test_zoom.html and dom/tests/mochitest/localstorage/test_localStorageQuotaPrivateBrowsing_perwindowpb.html:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=cb149ae1b86e8465abe3f32031676bc3e10f32e1
Attachment #8897905 - Attachment is obsolete: true
Attachment #8897905 - Flags: feedback?(mdeboer)
(Assignee)

Comment 73

3 months ago
Talos:

https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=22068d477a52c115bca1a07c8f059c912de3c430&newProject=try&newRevision=cb149ae1b86e8465abe3f32031676bc3e10f32e1&framework=1&showOnlyConfident=1

Updated

3 months ago
Whiteboard: [photon-performance][bugday-20140818] → [reserve-photon-performance][bugday-20140818]
Duplicate of this bug: 1392326
To clarify on why 1392326 ('newtab') is duped here, I couldn't tell if it was :home or :newtab since they both have a fox icon in the same exact place, but per discussion therein we're just going to assume it's this same issue.
(Assignee)

Updated

3 months ago
Attachment #8898917 - Attachment is obsolete: true
Comment hidden (mozreview-request)
(Assignee)

Updated

3 months ago
Attachment #8864038 - Flags: review+ → review?(mdeboer)
(Assignee)

Comment 77

3 months ago
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b03b39fe82d67bd1235650e3bdded6a3c51630c5
Comment on attachment 8864038 [details]
Bug 1054740 - When a session should be restored, don't load the homepage before the session file has been read.

https://reviewboard.mozilla.org/r/135762/#review177432

Alright, this looks very good! I would've r+'d this with comments addressed, but since this is a really critical path type of patch, I'd rather see it once more before landing. I hope you don't mind!

::: browser/base/content/browser.js:1682
(Diff revision 4)
> +        // Such callers expect that window.arguments[0] is handled as a single URI.
> +        loadOneOrMoreURIs(uriToLoad, Services.scriptSecurityManager.getSystemPrincipal());
> +      }
> +    });
> +
> +    let initiallyFocusedElement = document.commandDispatcher.focusedElement;

I see how you refactored this - and I highly appreciate that you're showing me this version first - but can you move the `initiallyFocusedElement` and `firstBrowserPaintDeferred` part above the first `this._uriToLoadPromise.then(...)` and _at least_ chain the two `then`s?

If you find it better to unify the two; even better I guess.

::: browser/base/content/browser.js:1684
(Diff revision 4)
> +      }
> +    });
> +
> +    let initiallyFocusedElement = document.commandDispatcher.focusedElement;
> +
> +    let firstBrowserPaintDeferred = (() => {

Why the IIFE here? This looks the same to me:

```js
let firstBrowserPaintDeferred = {};
firstBrowserPaintDeferred.promise = new Promise(resolve => {
  firstBrowserPaintDeferred.resolve = resolve;
});
```

::: browser/base/content/browser.js:1804
(Diff revision 4)
> -                        .getService(Ci.nsIBrowserHandler)
> +                          .getService(Ci.nsIBrowserHandler)
> -                        .defaultArgs;
> +                          .defaultArgs;
>  
> -    // If the given URI matches defaultArgs (the default homepage) we want
> -    // to block its load if we're going to restore a session anyway.
> -    if (uri == defaultArgs && sessionStartup.willOverrideHomepage)
> +      // If the given URI is different from the homepage, we want to load it.
> +      if (uri != defaultArgs) {
> +        resolve(uri);

Please don't forget a `return;` here, as it will most certainly race with the block below.

::: browser/components/sessionstore/nsSessionStartup.js:330
(Diff revision 4)
> -      let windows = this._initialState.windows || null;
> -      // If there are valid windows with not only pinned tabs, signal that we
> -      // will override the default homepage by restoring a session.
> -      return windows && windows.some(w => w.tabs.some(t => !t.pinned));
> +    // enabled via prefs, go ahead and load the homepage. We may still replace
> +    // it when recovering from a crash, which we'll only know after reading the
> +    // session file, but waiting for that would delay loading the homepage in
> +    // the non-crash case.
> +    if (!this._initialState && !this._resumeSessionEnabled) {
> +      return new Promise(resolve => {

Please use `return Promise.resolve(false);` here.

::: browser/components/sessionstore/nsSessionStartup.js:336
(Diff revision 4)
> -   * this to not start loading the homepage if we're going to stop its load
> -   * anyway shortly after.
> -   */
> -  get willOverrideHomepagePromise() {
>      return new Promise(resolve => {
> -      resolve(this.willOverrideHomepage);
> +      this.onceInitialized.then(() => {

My gut tells me that _if_ there's going to be any follow-up work, it'll be related to this line. Not that I know what - again, my gut tells me Talos sessionrestore - but hopefully not!
Attachment #8864038 - Flags: review?(mdeboer) → review-
(Assignee)

Comment 79

3 months ago
(In reply to Mike de Boer [:mikedeboer] from comment #78)
> If you find it better to unify the two; even better I guess.

I don't think that's better.
Comment hidden (mozreview-request)
(Assignee)

Comment 81

3 months ago
https://treeherder.mozilla.org/#/jobs?repo=try&revision=d0b254c80ded7996d0052e40016cfb675eb8c914
Comment on attachment 8864038 [details]
Bug 1054740 - When a session should be restored, don't load the homepage before the session file has been read.

https://reviewboard.mozilla.org/r/135762/#review177482

Thanks for the edits ;-) Ship it, please!
Attachment #8864038 - Flags: review?(mdeboer) → review+
(Assignee)

Comment 83

3 months ago
(In reply to Mike de Boer [:mikedeboer] from comment #78)
> I see how you refactored this - and I highly appreciate that you're showing
> me this version first - but can you move the `initiallyFocusedElement` and
> `firstBrowserPaintDeferred` part above the first
> `this._uriToLoadPromise.then(...)` and _at least_ chain the two `then`s?

*Sigh* this breaks tests again. Are you okay with reverting this?
Flags: needinfo?(mdeboer)
Comment hidden (mozreview-request)
(Assignee)

Comment 85

3 months ago
https://treeherder.mozilla.org/#/jobs?repo=try&revision=087a761c541b9486595ad9022df3374616601cd3
(Assignee)

Updated

3 months ago
Flags: needinfo?(mdeboer)
Attachment #8864038 - Flags: review+ → review?(mdeboer)
Comment on attachment 8864038 [details]
Bug 1054740 - When a session should be restored, don't load the homepage before the session file has been read.

https://reviewboard.mozilla.org/r/135762/#review177522
Attachment #8864038 - Flags: review?(mdeboer) → review+

Comment 87

3 months ago
Pushed by dgottwald@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/07c2203ca05e
When a session should be restored, don't load the homepage before the session file has been read. r=mikedeboer

Comment 88

3 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/07c2203ca05e
Status: REOPENED → RESOLVED
Last Resolved: 7 months ago3 months ago
status-firefox57: --- → fixed
Resolution: --- → FIXED

Updated

3 months ago
Iteration: --- → 57.2 - Aug 29
(Reporter)

Comment 89

3 months ago
Revisited this after I saw it flagged fixed. I'm a little amazed as to the solution.

I have a single question, because I'm probably missing something here that requires this kind of double promise way to do this:
Is there a situation where browser.startup.page is set to 3 (restore) that will not override the home page, and if so, what would that situation be?

I'm wondering because it would be 10,000x simpler and a hell of a lot faster to just check for the pref in willOverrideHomepage() and return true if 3, preventing the load...
(Assignee)

Updated

3 months ago
Depends on: 1393813
(Assignee)

Comment 90

3 months ago
(In reply to Mark Straver from comment #89)
> Revisited this after I saw it flagged fixed. I'm a little amazed as to the
> solution.
> 
> I have a single question, because I'm probably missing something here that
> requires this kind of double promise way to do this:
> Is there a situation where browser.startup.page is set to 3 (restore) that
> will not override the home page, and if so, what would that situation be?

Corrupt session file, or a saved session without any browser windows (not sure how easy it is to get into that situation these days), or a saved session containing pinned tabs only.

> I'm wondering because it would be 10,000x simpler and a hell of a lot faster
> to just check for the pref in willOverrideHomepage() and return true if 3,
> preventing the load...

Faster how? Deciding that we want to load the home page after the session file has been read shouldn't slow down anything else.
(Reporter)

Comment 91

3 months ago
(In reply to Dão Gottwald [::dao] from comment #90)
> Corrupt session file, or a saved session without any browser windows (not
> sure how easy it is to get into that situation these days), or a saved
> session containing pinned tabs only.
OK, so corner cases.
But, wouldn't that just result in a blank tab, then? Probably still better than loading an unwanted page.

If there are just pinned tabs and that is the state the browser was exited in, the user would likely want to restore to that state too, instead of adding a new tab...?

> Faster how? Deciding that we want to load the home page after the session
> file has been read shouldn't slow down anything else.
Well, seems to me that you're postponing a decision you can make early, until after the session file has been completely read. I don't see how that is not slower than just deciding at the start whether you want to initiate a load of the home page or not (in effect it'd be the same as doing it synchronous, but then with extra delays to resolve the promises). It certainly seems to me that skipping all that logic will help browser startup speed.
In addition, if loading the session store takes a long time (my average load time seems to be in the realm of 3-4 seconds before the home page is replaced, and my session is hardly extravagant with a dozen or so tabs) the user may already have interacted before you decide what you want to load in the tab, potentially interfering with a user-initiated action.

Just trying to understand why you can't keep it simple, instead.
(Assignee)

Comment 92

3 months ago
(In reply to Mark Straver from comment #91)
> (In reply to Dão Gottwald [::dao] from comment #90)
> > Corrupt session file, or a saved session without any browser windows (not
> > sure how easy it is to get into that situation these days), or a saved
> > session containing pinned tabs only.
> OK, so corner cases.
> But, wouldn't that just result in a blank tab, then? Probably still better
> than loading an unwanted page.

No, a blank tab isn't better than the homepage.

> If there are just pinned tabs and that is the state the browser was exited
> in, the user would likely want to restore to that state too, instead of
> adding a new tab...?

Maybe, maybe not. The user may be in that state because they closed all normal tabs before quitting, not because they necessarily did anything with their pinned tabs.

> > Faster how? Deciding that we want to load the home page after the session
> > file has been read shouldn't slow down anything else.
> Well, seems to me that you're postponing a decision you can make early,
> until after the session file has been completely read. I don't see how that
> is not slower than just deciding at the start whether you want to initiate a
> load of the home page or not (in effect it'd be the same as doing it
> synchronous, but then with extra delays to resolve the promises).

We're loading the homepage early if session restore is disabled. What case exactly is slower?
I have an outsider question - are there test cases in place for all of these described 'edge cases', and are they failing now that this commit is merged?
(Assignee)

Comment 94

3 months ago
(In reply to Richard Soderberg  [:atoll] from comment #93)
> I have an outsider question - are there test cases in place for all of these
> described 'edge cases',

Not sure... the sessionstore test collection is pretty extensive though.

> and are they failing now that this commit is merged?

No, they wouldn't be expected to fail. Tests are passing except one (bug 1393813).
(Reporter)

Comment 95

3 months ago
(In reply to Dão Gottwald [::dao] from comment #92)
> No, a blank tab isn't better than the homepage.

I beg to differ there. As a user, if I want to restore the windows and tabs from the last session, the browser shouldn't arbitrarily decide to open a tab and load what I have set as the homepage, instead, when it happens to not find any "regular" tabs to restore (whether that is because of a problem with the session store file or because of having only pinned tabs). If I wanted the home page loaded, it would either be in my session or I would have chosen "show my home page" instead.

> Maybe, maybe not. The user may be in that state because they closed all
> normal tabs before quitting, not because they necessarily did anything with
> their pinned tabs.

Exactly my point. If a user explicitly closes all tabs except pinned tabs before quitting, how is "restoring my windows and tabs from last time" implicitly including "and open a new tab with my home page" logical? It was not the state the browser was closed in. It's probably better to be consistent in your session state, I think.

> > > Faster how? Deciding that we want to load the home page after the session
> 
> We're loading the homepage early if session restore is disabled. What case
> exactly is slower?
The case where you are waiting for promises to be resolved :) I admit that's probably mostly theoretical, but the logic can definitely be made a lot simpler if all things are otherwise being equal.
session restore enabled -> load sessionstore -> restore tabs/windows
vs.
session restore enabled -> load session store -> perform checks for corner cases -> decide whether to load home page (-> load home page anyway, which may not be desired, see above) -> restore tabs/windows
(Assignee)

Comment 96

3 months ago
(In reply to Mark Straver from comment #95)
> (In reply to Dão Gottwald [::dao] from comment #92)
> > No, a blank tab isn't better than the homepage.
> 
> I beg to differ there.

Okay.

> > Maybe, maybe not. The user may be in that state because they closed all
> > normal tabs before quitting, not because they necessarily did anything with
> > their pinned tabs.
> 
> Exactly my point. If a user explicitly closes all tabs except pinned tabs
> before quitting, how is "restoring my windows and tabs from last time"
> implicitly including "and open a new tab with my home page" logical?

It gives the user a useful starting point, whereas there's a good chance that the right-most pinned tab isn't a useful starting point at all.

> > > > Faster how? Deciding that we want to load the home page after the session
> > 
> > We're loading the homepage early if session restore is disabled. What case
> > exactly is slower?
> The case where you are waiting for promises to be resolved :) I admit that's
> probably mostly theoretical, but the logic can definitely be made a lot
> simpler if all things are otherwise being equal.
> session restore enabled -> load sessionstore -> restore tabs/windows
> vs.
> session restore enabled -> load session store -> perform checks for corner
> cases -> decide whether to load home page (-> load home page anyway, which
> may not be desired, see above) -> restore tabs/windows

And where exactly is the bottom setup /slower/ than that above?
(Reporter)

Comment 97

3 months ago
(In reply to Dão Gottwald [::dao] from comment #96)
> It gives the user a useful starting point, whereas there's a good chance
> that the right-most pinned tab isn't a useful starting point at all.

People pin tabs for a reason. People close all other tabs before quitting for a reason, too, even in that corner case.

> And where exactly is the bottom setup /slower/ than that above?

Read again.
"the logic can definitely be made a lot simpler if all things are otherwise being equal."
Even if it won't make a noticeable difference (which it might or might not), keeping the logic simple with less code to walk is better.

But hey, if you prefer to defend your work regardless, then that's fine. I just wouldn't do it this way; seems overly complex and error-prone.
(Assignee)

Comment 98

3 months ago
(In reply to Mark Straver from comment #97)
> (In reply to Dão Gottwald [::dao] from comment #96)
> > It gives the user a useful starting point, whereas there's a good chance
> > that the right-most pinned tab isn't a useful starting point at all.
> 
> People pin tabs for a reason. People close all other tabs before quitting
> for a reason, too, even in that corner case.

People close tabs in order to get rid of them, not necessarily to select the right-most pinned tab as a starting point for their next session.

> > And where exactly is the bottom setup /slower/ than that above?
> 
> Read again.
> "the logic can definitely be made a lot simpler if all things are otherwise
> being equal."

Which wasn't the question. The question was about your claim that this setup slows things down.
(Reporter)

Comment 99

3 months ago
(In reply to Dão Gottwald [::dao] from comment #98)
> People close tabs in order to get rid of them, not necessarily to select the
> right-most pinned tab as a starting point for their next session.

Once more: People restore a session to resume where they left off. That doesn't imply opening a new tab with the home page.

> 
> > > And where exactly is the bottom setup /slower/ than that above?
> > 
> > Read again.
> > "the logic can definitely be made a lot simpler if all things are otherwise
> > being equal."
> 
> Which wasn't the question. The question was about your claim that this setup
> slows things down.
I think I have already answered that question. No matter how many times i reword it, it won't make a difference. I've said all i had to say, you can make up your own dam mind from this point forward.

I wrote out the two paths to illustrate the complexity of logic, not to make a point that one would be measurably faster than the other. Hence (once again) "if all things are otherwise being equal".
There is certainly a theoretical speed difference if you end up waiting for several promises to resolve before you can move forward. For the end user, in the "non corner case" it won't make a difference, of course.

I'm done here. You can choose whichever solution you think best, because i have better things to do than argue about differing opinions what is "better".
I'd like very much to see a coherent user story around the behaviors discussed in this bug, and then a post-57 evaluation of Firefox against that story, so that we (as opposed to today) clearly define our intended UX and can file bugs and add tests to bring the browser into line with that story. The feedback on all sides has been valuable, but it seems like there just isn't a well-spec'd story that covers the scenarios under discussion.

Updated

3 months ago
Blocks: 1393923
(Assignee)

Updated

3 months ago
No longer blocks: 1393923

Comment 101

2 months ago
Though the flags don't show it I guess this bug is also present in FF56. Can this be uplifted?
(Assignee)

Comment 102

2 months ago
(In reply to avada from comment #101)
> Though the flags don't show it I guess this bug is also present in FF56. Can
> this be uplifted?

No, this is too big a change / too risky for 56 at this point.
status-firefox55: --- → wontfix
status-firefox56: --- → wontfix
Target Milestone: Firefox 55 → Firefox 57
Blocks: 1364304
No longer blocks: 1364304

Updated

2 months ago
Duplicate of this bug: 1185158
You need to log in before you can comment on or make changes to this bug.