Closed Bug 1353013 Opened 7 years ago Closed 5 years ago

Kick off preloading about:newtab at a better time

Categories

(Firefox :: New Tab Page, enhancement, P2)

Product:
Firefox
Component:
New Tab Page
Type:
enhancement

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 68
Tracking Flags:
Tracking Status
firefox57 --- wontfix
firefox58 --- wontfix
firefox59 --- wontfix
firefox68 --- fixed

People

(Reporter: mconley, Assigned: Gijs)

References

(Depends on 1 open bug, Blocks 3 open bugs)

Details

(Keywords: memory-footprint, perf, Whiteboard: [fxperf:p1])

Attachments

(5 files, 7 obsolete files)

Bug 1353013 - Wait for inner and outer window nukings before completing shutdown leaks in content processes.
59 bytes, text/x-review-board-request
Details
Bug 1353013 - Schedule preloading about:newtab via idleCallback.
59 bytes, text/x-review-board-request
Details
Bug 1353013 - move new tab preload browser tracking into a separate module, r?dthayer
47 bytes, text/x-phabricator-request
Details | Review
Bug 1353013 - allow using the preloaded new tab page in private windows, too, r?dthayer
47 bytes, text/x-phabricator-request
Details | Review
Bug 1353013 - create preloaded newtab browser from an idle task, only in top window(s), r?dthayer
47 bytes, text/x-phabricator-request
Details | Review 
We have a newtab preloader per browser window. The preloaded browser is created after the first new tab is opened in that window[1].

This means that if you open a new window, you essentially "reset" the preloaded behaviour for the first newtab open in that window, and you only get the preloaded behaviour again after that first newtab in that window is opened.

Is there a better time when we can preload that about:newtab?

Note also that about:newtab and about:home is slated to be replaced by Activity Stream Real Soon Now.

What I suggest is to try using window.requestIdleCallback to preload the newtab when we feel that the browser is "idle":

https://developer.mozilla.org/en-US/docs/Web/API/Window/requestIdleCallback

I suggest some probes to go along with this:

1) How long since a window has opened before the first new tab is preloaded
2) How long it takes to preload the new tab
3) How often a new tab is opened and the preloaded tab is not available

[1]: http://searchfox.org/mozilla-central/rev/990055a4902952e038cc350c9ffe1ac426d1c943/browser/base/content/tabbrowser.xml#6428
Component: Location Bar → New Tab Page
Whiteboard: [photon]
I also thought about preloading the about:newtab page better. Two ideas I came up with:

- we currently load the about:newtab page for the first time when the user clicks the "+" button. We could start loading it when the user moves the mouse over that + button.

- we display about:newtab fast the second time by swapping docshells. I don't see what prevents us from doing docshell swapping across windows, as long as we keep creating a second about:newtab page in the edge case where the existing about:newtab page is currently the selected tab in an existing window.
(In reply to Florian Quèze [:florian] [:flo] from comment #1)
> - we currently load the about:newtab page for the first time when the user
> clicks the "+" button. We could start loading it when the user moves the
> mouse over that + button.

Yep, that's not a bad idea either - though I wonder how much time there is between the user hovering that button, and the user clicking that button...

That also doesn't take the Ctrl-T keyboard shortcut into account.

> - we display about:newtab fast the second time by swapping docshells.

I thought this was the case as well, but that's no longer true. Bug 1077652 switched us over to swapping in a background <xul:browser> instead of doing a DocShell / Frameloader swap. In fact, bug 1077652 switched us _away_ from having a global preloaded about:newtab.
See Also: → 1077652
(In reply to Mike Conley (:mconley) (Very high latency until April 3rd) from comment #2)
> (In reply to Florian Quèze [:florian] [:flo] from comment #1)
> > - we currently load the about:newtab page for the first time when the user
> > clicks the "+" button. We could start loading it when the user moves the
> > mouse over that + button.
> 
> Yep, that's not a bad idea either - though I wonder how much time there is
> between the user hovering that button, and the user clicking that button...
> 
> That also doesn't take the Ctrl-T keyboard shortcut into account.

I would expect the time between the mouseover and click events to be significantly longer than between mousedown and click (mouseup). And the latter is already ~100ms on average if I remember correctly the data phlsa showed me.

Note that I mostly have in mind the case of users interacting mostly with the mouse (ie. not me; I use Cmd+T all the time...). I think they are the majority.

> > - we display about:newtab fast the second time by swapping docshells.
> 
> I thought this was the case as well, but that's no longer true. Bug 1077652
> switched us over to swapping in a background <xul:browser> instead of doing
> a DocShell / Frameloader swap. In fact, bug 1077652 switched us _away_ from
> having a global preloaded about:newtab.

So the bug description there says that swapping a xul:browser within a window is faster than swapping a docshell from the hidden window... but I wonder if there was a reason to not combine the two approach, and do a docshell swap when it's across different windows, and a xul:browser swap when it's in the same window.
(In reply to Florian Quèze [:florian] [:flo] from comment #3)
> So the bug description there says that swapping a xul:browser within a
> window is faster than swapping a docshell from the hidden window... but I
> wonder if there was a reason to not combine the two approach, and do a
> docshell swap when it's across different windows, and a xul:browser swap
> when it's in the same window.

Doubtful if ttaubert or dao remembers (this landed quite a while ago), but let's check.
Flags: needinfo?(dao+bmo)
Flags: qe-verify-
Priority: -- → P2
Whiteboard: [photon] → [photon-performance]
(In reply to Mike Conley (:mconley) - At work week, slow to respond from comment #4)
> (In reply to Florian Quèze [:florian] [:flo] from comment #3)
> > So the bug description there says that swapping a xul:browser within a
> > window is faster than swapping a docshell from the hidden window... but I
> > wonder if there was a reason to not combine the two approach, and do a
> > docshell swap when it's across different windows, and a xul:browser swap
> > when it's in the same window.
> 
> Doubtful if ttaubert or dao remembers (this landed quite a while ago), but
> let's check.

Probably wasn't considered worth the complexity.
Flags: needinfo?(dao+bmo)
Priority: P2 → P3
Whiteboard: [photon-performance] → [reserve-photon-performance]
Attached patch prototype patch (obsolete) — — Splinter Review 
This works but regresses talos:

https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=d91d968b3081b2c7fca4eba85c9c6765780489dd&newProject=try&newRevision=30b29ec75a7b1c4cdf0ed2d8865796b9dfa968b7&framework=1&showOnlyConfident=1

This might be expected. I suspect tpo5 never opens a new tab without a specific URL, so it doesn't hit about:newtab preloading at all without this patch. I'm however a bit disappointed that requestIdleCallback doesn't prevent the responsiveness regression.
Attachment #8886645 - Flags: feedback?(florian)
Assignee: nobody → dao+bmo
Status: NEW → ASSIGNED
Priority: P3 → P1
Comment on attachment 8886645 [details] [diff] [review]
prototype patch

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

Looks reasonable, and sorry for the delay before I looked at this patch.

I'm afraid I can't really help with the Talos regressions, Mike is the expert on this, so forwarding to him.

::: browser/base/content/tabbrowser.xml
@@ +2045,5 @@
> +
> +              window.requestIdleCallback(() => this._createPreloadBrowser());
> +            }
> +          };
> +          Services.idle.addIdleObserver(this._preloadBrowserIdleObserver, 1);

this._preloadBrowserMinUserIdleSeconds instead of '1'?
Attachment #8886645 - Flags: feedback?(mconley)
Attachment #8886645 - Flags: feedback?(florian)
Attachment #8886645 - Flags: feedback+
Blocks: 1383593
So I gathered some profiles, and one thing that stands out immediately is that without this patch, there's a single content process... and with the patch, there are 3.

Obviously there's a content process for the pages we're loading in the tab... and I guess there'll be a content process for the preloaded page now that Activity Stream loads in the content process... not sure where that third one is coming from. I'm not sure if the increase in content processes is in any way related to the drag on event responsiveness, but it's all that's really standing out to me in these profiles.

I wonder if that third content process is for the thumbnailer?

I'm going to re-push with browser-thumbnails.js neutered to see how that affects things.
So I (finally!) got back around to this.

I had to re-base the patch a bit, but here is a comparison against yesterday's mozilla-central:

https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=98818f8b3ac5&newProject=try&newRevision=413556ac2c16&framework=1

So the characteristics have changed. The responsiveness regression is gone. Instead, I see tresize regressions and a tsvg_static regression. I suspect the tsvg_static one can be avoided by disabling preloading in that test (tsvg really only cares about SVG rendering performance - noise caused by the rest of the browser is... noise).

The tresize one is more interesting, and I'll investigate that next.
Comment on attachment 8886645 [details] [diff] [review]
prototype patch

Wow, sorry for the massive delay. I have news.

So I poked at this a bit today, and it turns out that even if the browser is doing something very frequently (say, resizing the window every 20ms or so after a paint, like what tresize does), an idle callback might still fire. Heck, I was able to shrink that window down to 0ms after each paint, and idle callbacks _still_ fired.

There are little zones of idleness between the resize, the paint, and the next resize, and so the preloaded browser is getting loaded in there. That's causing us to do work that (I believe) is adding noise to the tsvg and tresize tests.

One thing we might do:

Callbacks passed to requestIdleCallback get passed an IdleDeadline object[1]. The IdleDeadline object has a timeRemaining() method on it that returns an estimate of how much time is remaining in the idle period.

What I propose is that we have our idle callback check the timeRemaining(), and make sure it's greater than some threshold - otherwise, we postpone.

I'll post a patch trying that shortly and push it to try.

[1]: https://developer.mozilla.org/en-US/docs/Web/API/IdleDeadline
Flags: needinfo?(mconley)
Attachment #8886645 - Flags: feedback?(mconley) → feedback+
That appears to have done it for both tsvg / tscroll.

Hey dao, did you still want to do this, or can I take it off your hands?
Flags: needinfo?(mconley) → needinfo?(dao+bmo)
Assignee: dao+bmo → mconley
Flags: needinfo?(dao+bmo)
Iteration: --- → 57.2 - Aug 29
Whiteboard: [reserve-photon-performance] → [photon-performance]
Attachment #8900932 - Attachment is obsolete: true
Attachment #8886645 - Attachment is obsolete: true
Iteration: 57.2 - Aug 29 → 57.3 - Sep 19
Comment on attachment 8900931 [details]
Bug 1353013 - Be less aggressive about preloading about:newtab.

https://reviewboard.mozilla.org/r/172378/#review179562

Looks good to me.

::: browser/base/content/tabbrowser.xml:2057
(Diff revision 2)
>            ]]>
>          </body>
>        </method>
>  
> +      <field name="_preloadBrowserMinUserIdleSeconds">1</field>
> +      <field name="_preloadBrowserMinIdlePeriodMs">40</field>

I'm surprised we can get an idle deadline that's longer than a frame, but I assume you have tested this :-).

::: browser/base/content/tabbrowser.xml:2069
(Diff revision 2)
> +              !this._isPreloadingEnabled()) {
> +            return;
> +          }
> +
> +          this._preloadBrowserIdleObserver = (aSubject, aTopic) => {
> +            if (aTopic == "idle") {

nit: return early instead to reduce the indent of the whole function?

::: browser/base/content/tabbrowser.xml:2072
(Diff revision 2)
> +              this._preloadBrowserIdleObserver = null;
> +
> +              let idleCallback = (deadline) => {

nit: you don't need the parenthesis
Attachment #8900931 - Flags: review?(florian) → review+
Comment on attachment 8900931 [details]
Bug 1353013 - Be less aggressive about preloading about:newtab.

https://reviewboard.mozilla.org/r/172378/#review179562

> I'm surprised we can get an idle deadline that's longer than a frame, but I assume you have tested this :-).

Indeed I have!

> nit: return early instead to reduce the indent of the whole function?

Good idea.
Pushed by mconley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/5d320d8864e9
Be less aggressive about preloading about:newtab. r=florian
Backed out for failing e.g. test_accessiblecaret_cursor_mode.py of Marionette headless on OS X:

https://hg.mozilla.org/integration/autoland/rev/5ea49e6b1af6164ddf78dee5fe00c2a947b0bfcf

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=5d320d8864e90aa9684462251fee5b60f055ea9b&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable

Marionette failure: https://treeherder.mozilla.org/logviewer.html#?job_id=128643966&repo=autoland
TEST-UNEXPECTED-FAIL | test_accessiblecaret_cursor_mode.py AccessibleCaretCursorModeTestCase.test_caret_not_jump_when_dragging_to_editable_content_boundary_contenteditable | AssertionError: u'ABCDEFGHI!' == u'ABCDEFGHI!'

a11y failure (at least on Linux stylo): https://treeherder.mozilla.org/logviewer.html#?job_id=128646572&repo=autoland
> FAIL | accessible/tests/mochitest/relations/test_tabbrowser.xul | [ 'notificationbox node', address: [object XULElement] ] is not a target of relation of 'label for' type for '[ 'tab node', address: [object XULElement] ]'. 

chrome failure on Linux: https://treeherder.mozilla.org/logviewer.html#?job_id=128646579&repo=autoland
> TEST-UNEXPECTED-FAIL | layout/style/test/chrome/test_hover.html | Test timed out.
Flags: needinfo?(mconley)
This also triggers assertions on stylo: https://treeherder.mozilla.org/logviewer.html#?job_id=128646780&repo=autoland

[task 2017-09-05T20:21:36.683712Z] 20:21:36     INFO - TEST-START | dom/events/test/test_bug336682_1.html
[task 2017-09-05T20:21:36.726594Z] 20:21:36     INFO - GECKO(1641) | [Child 1687] WARNING: stylo: ServoStyleSets cannot respond to document state changes yet (only matters for chrome documents). See bug 1290285.: file /builds/worker/workspace/build/src/layout/base/PresShell.cpp, line 4318
[task 2017-09-05T20:21:36.866211Z] 20:21:36     INFO - GECKO(1641) | ++DOMWINDOW == 49 (0x7fc66291c800) [pid = 1687] [serial = 64] [outer = 0x7fc666acb800]
[task 2017-09-05T20:21:36.963378Z] 20:21:36     INFO - GECKO(1641) | [Child 1687] WARNING: stylo: Web Components not supported yet: file /builds/worker/workspace/build/src/dom/base/nsDocument.cpp, line 6418
[task 2017-09-05T20:21:36.972717Z] 20:21:36     INFO - GECKO(1641) | [Child 1687] WARNING: stylo: Web Components not supported yet: file /builds/worker/workspace/build/src/dom/base/nsDocument.cpp, line 6418
[task 2017-09-05T20:21:37.211619Z] 20:21:37     INFO - GECKO(1641) | [Child 1687] WARNING: stylo: ServoStyleSets cannot respond to document state changes yet (only matters for chrome documents). See bug 1290285.: file /builds/worker/workspace/build/src/layout/base/PresShell.cpp, line 4318
[task 2017-09-05T20:21:37.430673Z] 20:21:37     INFO - GECKO(1641) | Assertion failure: IsSafeToRun(), at /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/SchedulerGroup.h:74
[task 2017-09-05T20:22:31.219134Z] 20:22:31     INFO - GECKO(1641) | #01: nsDocument::GetEventTargetParent [dom/base/nsDocument.cpp:8312]
[task 2017-09-05T20:22:31.219613Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.221953Z] 20:22:31     INFO - GECKO(1641) | #02: mozilla::EventTargetChainItem::GetEventTargetParent [dom/events/EventDispatcher.cpp:211]
[task 2017-09-05T20:22:31.222182Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.223984Z] 20:22:31     INFO - GECKO(1641) | #03: mozilla::EventDispatcher::Dispatch [dom/events/EventDispatcher.cpp:788]
[task 2017-09-05T20:22:31.225633Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.227447Z] 20:22:31     INFO - GECKO(1641) | #04: mozilla::EventDispatcher::DispatchDOMEvent [dom/events/EventDispatcher.cpp:892]
[task 2017-09-05T20:22:31.230305Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.234408Z] 20:22:31     INFO - GECKO(1641) | #05: nsINode::DispatchEvent [dom/base/nsINode.cpp:1342]
[task 2017-09-05T20:22:31.235988Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.238477Z] 20:22:31     INFO - GECKO(1641) | #06: nsContentUtils::DispatchEvent [dom/base/nsContentUtils.cpp:4554]
[task 2017-09-05T20:22:31.240973Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.243860Z] 20:22:31     INFO - GECKO(1641) | #07: nsContentUtils::DispatchTrustedEvent [dom/base/nsContentUtils.cpp:4524]
[task 2017-09-05T20:22:31.246848Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.248821Z] 20:22:31     INFO - GECKO(1641) | #08: nsGlobalWindow::FireOfflineStatusEventIfChanged [dom/base/nsGlobalWindow.cpp:11549]
[task 2017-09-05T20:22:31.251614Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.254611Z] 20:22:31     INFO - GECKO(1641) | #09: nsGlobalWindow::Observe [dom/base/nsGlobalWindow.cpp:12188]
[task 2017-09-05T20:22:31.256805Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.259290Z] 20:22:31     INFO - GECKO(1641) | #10: nsObserverList::NotifyObservers [xpcom/ds/nsObserverList.cpp:111]
[task 2017-09-05T20:22:31.261861Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.264582Z] 20:22:31     INFO - GECKO(1641) | #11: nsObserverService::NotifyObservers [xpcom/ds/nsTHashtable.h:136]
[task 2017-09-05T20:22:31.266879Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.268880Z] 20:22:31     INFO - GECKO(1641) | #12: mozilla::net::nsIOService::SetOffline [netwerk/base/nsIOService.cpp:1157]
[task 2017-09-05T20:22:31.271751Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.274417Z] 20:22:31     INFO - GECKO(1641) | #13: NS_InvokeByIndex
[task 2017-09-05T20:22:31.278965Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.281870Z] 20:22:31     INFO - GECKO(1641) | #14: CallMethodHelper::Call [js/xpconnect/src/xpcprivate.h:776]
[task 2017-09-05T20:22:31.283595Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.286855Z] 20:22:31     INFO - GECKO(1641) | #15: XPCWrappedNative::CallMethod [js/xpconnect/src/XPCWrappedNative.cpp:1282]
[task 2017-09-05T20:22:31.288809Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.292098Z] 20:22:31     INFO - GECKO(1641) | #16: XPC_WN_GetterSetter [js/xpconnect/src/XPCWrappedNativeJSOps.cpp:957]
[task 2017-09-05T20:22:31.294523Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.297777Z] 20:22:31     INFO - GECKO(1641) | #17: js::CallJSNative [js/src/jscntxtinlines.h:294]
[task 2017-09-05T20:22:31.300000Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.301965Z] 20:22:31     INFO - GECKO(1641) | #18: js::InternalCallOrConstruct [js/src/vm/Interpreter.cpp:494]
[task 2017-09-05T20:22:31.304888Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.307698Z] 20:22:31     INFO - GECKO(1641) | #19: js::Call [js/src/vm/Interpreter.cpp:558]
[task 2017-09-05T20:22:31.310074Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.312606Z] 20:22:31     INFO - GECKO(1641) | #20: js::CallSetter [js/src/vm/Interpreter.cpp:686]
[task 2017-09-05T20:22:31.315038Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.318354Z] 20:22:31     INFO - GECKO(1641) | #21: SetExistingProperty [js/src/vm/NativeObject.cpp:2749]
[task 2017-09-05T20:22:31.320600Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.322590Z] 20:22:31     INFO - GECKO(1641) | #22: js::NativeSetProperty<(js::QualifiedBool)1u> [js/src/vm/NativeObject.cpp:2785]
[task 2017-09-05T20:22:31.325470Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.327920Z] 20:22:31     INFO - GECKO(1641) | #23: Reflect_set [js/src/vm/NativeObject.h:1555]
[task 2017-09-05T20:22:31.330510Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.333375Z] 20:22:31     INFO - GECKO(1641) | #24: js::CallJSNative [js/src/jscntxtinlines.h:294]
[task 2017-09-05T20:22:31.337539Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.339351Z] 20:22:31     INFO - GECKO(1641) | #25: js::InternalCallOrConstruct [js/src/vm/Interpreter.cpp:494]
[task 2017-09-05T20:22:31.340976Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.347414Z] 20:22:31     INFO - GECKO(1641) | #26: Interpret [js/src/vm/Interpreter.cpp:3093]
[task 2017-09-05T20:22:31.349067Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.350836Z] 20:22:31     INFO - GECKO(1641) | #27: js::RunScript [js/src/vm/Interpreter.cpp:405]
[task 2017-09-05T20:22:31.352395Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.355424Z] 20:22:31     INFO - GECKO(1641) | #28: js::InternalCallOrConstruct [js/src/vm/Interpreter.cpp:512]
[task 2017-09-05T20:22:31.358307Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.360286Z] 20:22:31     INFO - GECKO(1641) | #29: js::Call [js/src/vm/Interpreter.cpp:558]
[task 2017-09-05T20:22:31.366108Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.367949Z] 20:22:31     INFO - GECKO(1641) | #30: js::ScriptedProxyHandler::set [js/src/proxy/ScriptedProxyHandler.cpp:1082]
[task 2017-09-05T20:22:31.369541Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.371298Z] 20:22:31     INFO - GECKO(1641) | #31: js::Proxy::setInternal [js/src/proxy/Proxy.cpp:390]
[task 2017-09-05T20:22:31.374897Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.377509Z] 20:22:31     INFO - GECKO(1641) | #32: js::Proxy::set [js/src/proxy/Proxy.cpp:399]
[task 2017-09-05T20:22:31.379215Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.381323Z] 20:22:31     INFO - GECKO(1641) | #33: JSObject::nonNativeSetProperty [js/src/jsobj.cpp:1041]
[task 2017-09-05T20:22:31.383854Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.385805Z] 20:22:31     INFO - GECKO(1641) | #34: js::ForwardingProxyHandler::set [js/src/vm/NativeObject.h:1554]
[task 2017-09-05T20:22:31.389335Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.391158Z] 20:22:31     INFO - GECKO(1641) | #35: js::CrossCompartmentWrapper::set [js/src/proxy/CrossCompartmentWrapper.cpp:238]
[task 2017-09-05T20:22:31.392723Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.394564Z] 20:22:31     INFO - GECKO(1641) | #36: js::Proxy::setInternal [js/src/proxy/Proxy.cpp:390]
[task 2017-09-05T20:22:31.396165Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.399260Z] 20:22:31     INFO - GECKO(1641) | #37: js::Proxy::set [js/src/proxy/Proxy.cpp:399]
[task 2017-09-05T20:22:31.400888Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.402705Z] 20:22:31     INFO - GECKO(1641) | #38: JSObject::nonNativeSetProperty [js/src/jsobj.cpp:1041]
[task 2017-09-05T20:22:31.404248Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.406128Z] 20:22:31     INFO - GECKO(1641) | #39: js::SetProperty [js/src/vm/NativeObject.h:1556]
[task 2017-09-05T20:22:31.407667Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.410102Z] 20:22:31     INFO - GECKO(1641) | #40: Interpret [js/src/vm/Interpreter.cpp:268]
[task 2017-09-05T20:22:31.411646Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.413595Z] 20:22:31     INFO - GECKO(1641) | #41: js::RunScript [js/src/vm/Interpreter.cpp:405]
[task 2017-09-05T20:22:31.415176Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.421403Z] 20:22:31     INFO - GECKO(1641) | #42: js::InternalCallOrConstruct [js/src/vm/Interpreter.cpp:512]
[task 2017-09-05T20:22:31.423027Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.424819Z] 20:22:31     INFO - GECKO(1641) | #43: js::Call [js/src/vm/Interpreter.cpp:558]
[task 2017-09-05T20:22:31.429557Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.431361Z] 20:22:31     INFO - GECKO(1641) | #44: js::fun_apply [js/src/jsfun.cpp:1306]
[task 2017-09-05T20:22:31.432927Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.434695Z] 20:22:31     INFO - GECKO(1641) | #45: js::CallJSNative [js/src/jscntxtinlines.h:294]
[task 2017-09-05T20:22:31.436235Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.438027Z] 20:22:31     INFO - GECKO(1641) | #46: js::InternalCallOrConstruct [js/src/vm/Interpreter.cpp:494]
[task 2017-09-05T20:22:31.439815Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.443847Z] 20:22:31     INFO - GECKO(1641) | #47: Interpret [js/src/vm/Interpreter.cpp:3093]
[task 2017-09-05T20:22:31.445446Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.447196Z] 20:22:31     INFO - GECKO(1641) | #48: js::RunScript [js/src/vm/Interpreter.cpp:405]
[task 2017-09-05T20:22:31.448770Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.450541Z] 20:22:31     INFO - GECKO(1641) | #49: js::InternalCallOrConstruct [js/src/vm/Interpreter.cpp:512]
[task 2017-09-05T20:22:31.453344Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.455133Z] 20:22:31     INFO - GECKO(1641) | #50: js::Call [js/src/vm/Interpreter.cpp:558]
[task 2017-09-05T20:22:31.456772Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.460209Z] 20:22:31     INFO - GECKO(1641) | #51: JS::Call [js/src/jsapi.cpp:2937]
[task 2017-09-05T20:22:31.461806Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.463868Z] 20:22:31     INFO - GECKO(1641) | #52: mozilla::dom::EventHandlerNonNull::Call [s3:gecko-generated-sources:a74e9167ed4abbea1a7e9c415f889f61cd08d508be96276b8e3ab3a810441ec213bf1f2f7e0a571d855d6c770f010a4bda5422bbef494642dc5e121077b09766/dom/bindings/EventHandlerBinding.cpp::260]
[task 2017-09-05T20:22:31.466840Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.468984Z] 20:22:31     INFO - GECKO(1641) | #53: mozilla::JSEventHandler::HandleEvent [s3:gecko-generated-sources:d0cd062a8f2e61a1842e705e1539dafa6e2559f266e0cf39cc24ecbc1de67828060d8f7d4015631bcfe7c22d53ac77e562e84587fe96e76b41b346b32ed4aeb6/dist/include/mozilla/dom/EventHandlerBinding.h::357]
[task 2017-09-05T20:22:31.470632Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.473692Z] 20:22:31     INFO - GECKO(1641) | #54: mozilla::EventListenerManager::HandleEventSubType [dom/events/EventListenerManager.cpp:1114]
[task 2017-09-05T20:22:31.475293Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.481150Z] 20:22:31     INFO - GECKO(1641) | #55: mozilla::EventListenerManager::HandleEventInternal [dom/events/EventListenerManager.cpp:1283]
[task 2017-09-05T20:22:31.482809Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.484619Z] 20:22:31     INFO - GECKO(1641) | #56: mozilla::EventTargetChainItem::HandleEvent [dom/events/EventListenerManager.h:376]
[task 2017-09-05T20:22:31.486199Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.488019Z] 20:22:31     INFO - GECKO(1641) | #57: mozilla::EventTargetChainItem::HandleEventTargetChain [dom/events/EventDispatcher.cpp:462]
[task 2017-09-05T20:22:31.489619Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.491385Z] 20:22:31     INFO - GECKO(1641) | #58: mozilla::EventDispatcher::Dispatch [dom/events/EventDispatcher.cpp:827]
[task 2017-09-05T20:22:31.492939Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.494724Z] 20:22:31     INFO - GECKO(1641) | #59: nsDocumentViewer::LoadComplete [layout/base/nsDocumentViewer.cpp:1082]
[task 2017-09-05T20:22:31.497552Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.499323Z] 20:22:31     INFO - GECKO(1641) | #60: nsDocShell::EndPageLoad [docshell/base/nsDocShell.cpp:7726]
[task 2017-09-05T20:22:31.501980Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.503806Z] 20:22:31     INFO - GECKO(1641) | #61: nsDocShell::OnStateChange [docshell/base/nsDocShell.cpp:7522]
[task 2017-09-05T20:22:31.505517Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.507522Z] 20:22:31     INFO - GECKO(1641) | #62: nsDocLoader::DoFireOnStateChange [uriloader/base/nsDocLoader.cpp:1320]
[task 2017-09-05T20:22:31.509708Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.511704Z] 20:22:31     INFO - GECKO(1641) | #63: nsDocLoader::doStopDocumentLoad [uriloader/base/nsDocLoader.cpp:860]
[task 2017-09-05T20:22:31.516524Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.518413Z] 20:22:31     INFO - GECKO(1641) | #64: nsDocLoader::DocLoaderIsEmpty [uriloader/base/nsDocLoader.cpp:752]
[task 2017-09-05T20:22:31.520011Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.521865Z] 20:22:31     INFO - GECKO(1641) | #65: nsDocLoader::OnStopRequest [uriloader/base/nsDocLoader.cpp:625]
[task 2017-09-05T20:22:31.523466Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.525339Z] 20:22:31     INFO - GECKO(1641) | #66: mozilla::net::nsLoadGroup::RemoveRequest [netwerk/base/nsLoadGroup.cpp:631]
[task 2017-09-05T20:22:31.528238Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.530125Z] 20:22:31     INFO - GECKO(1641) | #67: nsDocument::DoUnblockOnload [dom/base/nsDocument.cpp:9247]
[task 2017-09-05T20:22:31.533761Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.535637Z] 20:22:31     INFO - GECKO(1641) | #68: nsDocument::UnblockOnload [dom/base/nsDocument.cpp:9171]
[task 2017-09-05T20:22:31.537258Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.539134Z] 20:22:31     INFO - GECKO(1641) | #69: nsDocument::DispatchContentLoadedEvents [dom/base/nsDocument.cpp:5558]
[task 2017-09-05T20:22:31.540844Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.542991Z] 20:22:31     INFO - GECKO(1641) | #70: mozilla::detail::RunnableMethodImpl<nsDocument*, void (nsDocument::*)(), true, (mozilla::RunnableKind)0u>::Run [xpcom/threads/nsThreadUtils.h:1196]
[task 2017-09-05T20:22:31.547339Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.549259Z] 20:22:31     INFO - GECKO(1641) | #71: mozilla::SchedulerGroup::Runnable::Run [xpcom/threads/SchedulerGroup.cpp:396]
[task 2017-09-05T20:22:31.550905Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.552723Z] 20:22:31     INFO - GECKO(1641) | #72: nsThread::ProcessNextEvent [mfbt/Maybe.h:445]
[task 2017-09-05T20:22:31.554366Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.557314Z] 20:22:31     INFO - GECKO(1641) | #73: NS_ProcessNextEvent [xpcom/threads/nsThreadUtils.cpp:521]
[task 2017-09-05T20:22:31.558958Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.561869Z] 20:22:31     INFO - GECKO(1641) | #74: mozilla::ipc::MessagePump::Run [ipc/glue/MessagePump.cpp:98]
[task 2017-09-05T20:22:31.563411Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.565259Z] 20:22:31     INFO - GECKO(1641) | #75: MessageLoop::RunInternal [ipc/chromium/src/base/message_loop.cc:327]
[task 2017-09-05T20:22:31.569983Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.571817Z] 20:22:31     INFO - GECKO(1641) | #76: MessageLoop::Run [ipc/chromium/src/base/message_loop.cc:298]
[task 2017-09-05T20:22:31.573436Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.575226Z] 20:22:31     INFO - GECKO(1641) | #77: nsBaseAppShell::Run [widget/nsBaseAppShell.cpp:160]
[task 2017-09-05T20:22:31.576810Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.578627Z] 20:22:31     INFO - GECKO(1641) | #78: XRE_RunAppShell [toolkit/xre/nsEmbedFunctions.cpp:823]
[task 2017-09-05T20:22:31.580455Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.584398Z] 20:22:31     INFO - GECKO(1641) | #79: mozilla::ipc::MessagePumpForChildProcess::Run [ipc/glue/MessagePump.cpp:269]
[task 2017-09-05T20:22:31.585997Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.587792Z] 20:22:31     INFO - GECKO(1641) | #80: MessageLoop::RunInternal [ipc/chromium/src/base/message_loop.cc:327]
[task 2017-09-05T20:22:31.589411Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.591252Z] 20:22:31     INFO - GECKO(1641) | #81: MessageLoop::Run [ipc/chromium/src/base/message_loop.cc:298]
[task 2017-09-05T20:22:31.595031Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.596839Z] 20:22:31     INFO - GECKO(1641) | #82: XRE_InitChildProcess [toolkit/xre/nsEmbedFunctions.cpp:695]
[task 2017-09-05T20:22:31.598381Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.616957Z] 20:22:31     INFO - GECKO(1641) | #83: content_process_main [ipc/contentproc/plugin-container.cpp:65]
[task 2017-09-05T20:22:31.617288Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.618901Z] 20:22:31     INFO - GECKO(1641) | #84: main [browser/app/nsBrowserApp.cpp:288]
[task 2017-09-05T20:22:31.619317Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.620915Z] 20:22:31     INFO - GECKO(1641) | #85: libc.so.6 + 0x20830
[task 2017-09-05T20:22:31.622476Z] 20:22:31     INFO - 
[task 2017-09-05T20:22:31.624231Z] 20:22:31     INFO - GECKO(1641) | #86: _start
This also seems to cause an intermittent failure in browser_startup.js
https://treeherder.mozilla.org/logviewer.html#?job_id=128675876&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=128668413&repo=autoland

This was originally attributed to bug 1392081, but it looked unlikely considered my changes only affect Places views that are not used by browser_startup.js
I retriggered the b-c tests multiple times (see bc11 on linux32-stylo-debug)
https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=cf5b68506bef58600c4e8ec1654102fd36bf0c52&selectedJob=128644629
https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=5d320d8864e90aa9684462251fee5b60f055ea9b&selectedJob=128861282

My theory is that by delaying about:newtab, something else is happening sooner. A possibility could be the Star button (TBV), since even if it's hidden, its onLocationChange handler will still be invoked and that will initialize Places. http://searchfox.org/mozilla-central/rev/4d8e389498a08668cce9ebf6232cc96be178c3e4/browser/base/content/browser-places.js#1814

Another possibility is that newtab itself somehow anticipates work, but from what Florian said this patch should only delay things...
Status: ASSIGNED → NEW
Iteration: 57.3 - Sep 19 → ---
Priority: P1 → P3
Whiteboard: [photon-performance] → [reserve-photon-performance]
(In reply to Marco Bonardo [::mak] from comment #24)
> My theory is that by delaying about:newtab, something else is happening
> sooner.

It's possible that it's simpler than that - the patch in here makes loading about:newtab less aggressive, but also makes it so that we attempt to preload one after first paint after 1 second of idle time and at least 40ms of idle callback budget.

Digging into this...
Flags: needinfo?(mconley)
Blocks: 1399961
Depends on: 1401214
Status: NEW → ASSIGNED
Priority: P3 → P1
Whiteboard: [reserve-photon-performance] → [reserve-photon-performance] [fxperf]
Priority: P1 → P2
Whiteboard: [reserve-photon-performance] [fxperf] → [fxperf:p2]
I think I've found a way to make this work.
Whiteboard: [fxperf:p2] → [fxperf:p1]
Attachment #8910804 - Attachment is obsolete: true
Attachment #8900931 - Attachment is obsolete: true
Attachment #8910805 - Attachment is obsolete: true
Attachment #8910806 - Attachment is obsolete: true
Blocks: 1453080
See Also: → 1436615
No longer blocks: 1453080
This is needed to avoid some intermittent shutdown leaks being reported from automation that
patches later in this series unhappily seem to trigger quite often.

MozReview-Commit-ID: 2HVOILBXWP
Attachment #8986520 - Attachment is obsolete: true
Whiteboard: [fxperf:p1] → [fxperf:p2]

Stealing this.

Assignee: mconley → gijskruitbosch+bugs
Blocks: 1522877
Whiteboard: [fxperf:p2] → [fxperf:p1]
See Also: → 1527081

This didn't use to work and was disabled in
https://bugzilla.mozilla.org/show_bug.cgi?id=1195981 . I expect my changes in
https://bugzilla.mozilla.org/show_bug.cgi?id=1427186 fixed the issue. It works
in my testing, anyway.

Depends on D21126

This limits us to 1 preloaded browser per window, in the top 3 normal windows + top 3 private windows.
If we try to create additional browsers beyond that, we instead move a pre-existing browser across.

Depends on D21127

Blocks: 1526416

My trypush is hitting orange in https://searchfox.org/mozilla-central/source/startupcache/test/browser_startupcache_telemetry.js , on Linux opt only. I expect what's happening is that the preload happens on the original window that opens for the test (it's the only browser test running in its dir, so the browser will have just opened before starting the test), and it (or some parts of it) happens after we invalidate the startup cache, causing us to add things to the startup cache which we then hit when we open the next window. I'll make the test wait for idle tasks in its own window to have finished, as they could all potentially be interfering here; hopefully that'll fix it.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=61bb81f07e2cfea4b4773414ca23983c44a28dbb

(In reply to :Gijs (he/him) from comment #40)

My trypush is hitting orange in https://searchfox.org/mozilla-central/source/startupcache/test/browser_startupcache_telemetry.js , on Linux opt only. I expect what's happening is that the preload happens on the original window that opens for the test (it's the only browser test running in its dir, so the browser will have just opened before starting the test), and it (or some parts of it) happens after we invalidate the startup cache, causing us to add things to the startup cache which we then hit when we open the next window. I'll make the test wait for idle tasks in its own window to have finished, as they could all potentially be interfering here; hopefully that'll fix it.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=61bb81f07e2cfea4b4773414ca23983c44a28dbb

As far as I can tell, this is caused by us loading RemoteController.js, cf. https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=233020134&repo=try&lineNumber=7443 .

I can't reproduce locally. I think what's actually happening is that:

  1. we load a new window
  2. the new window loads a browser for its initial tab, which hits construct() from the connectedCallback of the custom element, hitting https://searchfox.org/mozilla-central/rev/2f1020dc4176d38dd5f3d0496f3c46849862ee0b/toolkit/content/widgets/browser-custom-element.js#1076-1080 .
  3. we hit the idle task and create a preloaded browser, which hits this same codepath a second time. This time the remotecontroller.js file is memory cached, so we get a hit we don't expect
  4. the new window is focused and activated and whatnot, and the promise for openNewBrowserWindow() resolves, and we check telemetry.

I don't think this needs to block this bug landing, so what I'm going to do is:

  1. land with new tab preloading turned off in this test (after I get some sleep, anyway).
  2. file a follow-up bug for remotecontroller.js to be a jsm - there doesn't seem to be a good reason to use the subscript loader directly here and re-evaluate the global scope of that file every time we create a browser.
  3. file another follow-up depending on that to stop turning off new tab preloading in the test.

For (2) there, I guess I have to talk to Ehsan because I can't tell from the bug why we moved this to a plain JS file in bug 1395795.

Depends on: 1395795
Depends on: 1534172

There were some more issues with browser_statuspanel_twice.js, which I believe I've fixed (thanks to Doug for helping poke at logfiles). They seem to have been caused by changes in timings for the load in the window that opens, which cause state change events which then cause the "previoustype" and "type" attributes on the status panel to update, cancelling the transition at https://searchfox.org/mozilla-central/rev/8ff2cd0a27e3764d9540abdc5a66b2fb1e4e9644/browser/base/content/browser.css#1056-1058 .

However, we're now well into soft freeze, and this isn't technically a bugfix, so I'll land next week after soft freeze is over. I might still request uplift if there are no obvious/serious regressions.

Pushed by gijskruitbosch@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/976afd1adf84
move new tab preload browser tracking into a separate module, r=dthayer
https://hg.mozilla.org/integration/autoland/rev/a3d1302b06c0
allow using the preloaded new tab page in private windows, too, r=dthayer
https://hg.mozilla.org/integration/autoland/rev/af8bce2330e9
create preloaded newtab browser from an idle task, only in top window(s), r=dthayer
Backout by shindli@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/dde899c9bfb9
Backed out 3 changesets for a11y failures in accessible/tests/mochitest/relations/test_tabbrowser.xul CLOSED TREE
Pushed by gijskruitbosch@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/d37ddb68b340
move new tab preload browser tracking into a separate module, r=dthayer
https://hg.mozilla.org/integration/autoland/rev/ef5f455b726f
allow using the preloaded new tab page in private windows, too, r=dthayer
https://hg.mozilla.org/integration/autoland/rev/26973fbde8f4
create preloaded newtab browser from an idle task, only in top window(s), r=dthayer
Flags: needinfo?(gijskruitbosch+bugs)

https://hg.mozilla.org/mozilla-central/rev/d37ddb68b340
https://hg.mozilla.org/mozilla-central/rev/ef5f455b726f
https://hg.mozilla.org/mozilla-central/rev/26973fbde8f4

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox68: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 68
Depends on: 1537694
See Also: → 1540832
Regressions: 1542232
Blocks: 1602025
Blocks: 1616568
Regressions: 1675660
You need to log in before you can comment on or make changes to this bug.