Closed Bug 1398597 Opened 7 years ago Closed 7 years ago

[meta] Preferences/Options page takes a lot of time to open (3-5 sec), especially on first launch in a session

Categories

(Firefox :: Settings UI, defect)

Unspecified
Windows
defect
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 57
Tracking Status
firefox-esr52 --- unaffected
firefox55 --- unaffected
firefox56 + wontfix
firefox57 + fixed

People

(Reporter: itiel_yn8, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: perf, regression, Whiteboard: [photon-preference])

Attachments

(2 files)

My machine specs:
Intel i7-6700, 4GB RAM, 1TB HDD, Windows 10

https://perfht.ml/2eWxMYK
This profile was taken when opening the Options page for the first time on this specific session

https://perfht.ml/2eX4auf
And this one from when opening the Options page for a second time.

About the same can be seen on a MacBook Pro with 2.2 GHz Intel Core i7, 16 GB memory.
That's my MacBook Pro, 3 years old but still fast, so I don't think it depends on machine spec. If the issue can't be solved now, there should be at least a loading indicator. Seeing a blank page for 5 sec isn't a great experience.
Keywords: perf
[Tracking Requested - why for this release]: Actually this is a regression from Firefox 56 when the Preferences page is reorganized (in a bad way IMHO.) I can confirm that it takes 5 sec to load the page on 56 Developer Edition with a fresh profile.
Track 56+/57+ as performance impact.

Hi Ricky,
Is this issue under your coverage?
Flags: needinfo?(rchien)
Flags: needinfo?(rchien)
Whiteboard: [photon-preference][triage]
According to Font Book, I have 561 fonts now on my MacBook Pro.
Ricky, do you see any font-related code in these profiles? (I don't.)

It's unfortunate that these profiles don't contain symbols for xul.pdb. It's possible that the symbols were still downloading when you clicked "Share" in the profiler UI.

I don't see anything unusual on the profile of opening the preferences the second time.

In the profile of opening it for the first time, there's 530ms spent in _loadApplicationHandlers, and a little bit later 1060ms in SHGetFileInfoWStub.

So my guess is that the slow part here is initializing the 'Applications' section of the main pane.

The initialization of Sync is also causing 120ms of jank a little bit after first painting the preferences.
(In reply to Florian Quèze [:florian] [:flo] from comment #5)
> It's unfortunate that these profiles don't contain symbols for xul.pdb. It's
> possible that the symbols were still downloading when you clicked "Share" in
> the profiler UI.

Do you want me to re-share fresh results, after waiting a little so all symbols would get loaded?
(In reply to Itiel from comment #6)
> (In reply to Florian Quèze [:florian] [:flo] from comment #5)
> > It's unfortunate that these profiles don't contain symbols for xul.pdb. It's
> > possible that the symbols were still downloading when you clicked "Share" in
> > the profiler UI.
> 
> Do you want me to re-share fresh results, after waiting a little so all
> symbols would get loaded?

Would be nice, but not required, as we already know where to look for things that should be faster.
Florian, is this something we may fix before the 56 release or is it something we are going to accept?
Time is pretty tight, we only have the beta 13 build tomorrow and RC build next week before the release.
Flags: needinfo?(florian)
(In reply to Liz Henry (:lizzard) (needinfo? me) from comment #8)
> Florian, is this something we may fix before the 56 release or is it
> something we are going to accept?
> Time is pretty tight, we only have the beta 13 build tomorrow and RC build
> next week before the release.

So, assuming we decide to focus this bug on the slowness of initializing the 'Applications' section (ie. the slowest thing I've noticed in the profile), fixing it would involve changing the implementation to avoid main thread IO. That's completely out of the picture for 56, and very unlikely even for 57 at this point.

I would recommend wontfix for 56. For 57, we can probably 'hide' the problem or reduce its impact by ensuring the preferences page gets painted at least once before we start initializing the 'Applications' tree.
Flags: needinfo?(florian)
Thanks, that seems clear. I agree it is too late to focus on this for 56 if there isn't a quick fix.
Just curious, why no one noticed this regression during the 56 cycle? I thought the pref reorg has been reviewed by the Softvision QA team as well. I'm afraid this could happen again.
Keywords: regression
(In reply to Florian Quèze [:florian] [:flo] from comment #9)
> For 57, we can probably 'hide' the problem or reduce its impact by ensuring the preferences page gets painted at least once before we start initializing the 'Applications' tree.

Florian, what do you suggest about 'hide' or reduce its impact? Do you know any possible approach to lazy initializing the 'Applications' tree? Is it probably a quick fix during 57 cycle?
Flags: needinfo?(florian)
Flags: qe-verify+
Priority: -- → P2
QA Contact: hani.yacoub
Whiteboard: [photon-preference][triage] → [photon-preference]
Back in bug 1389550 I was investigating ways to hook a callback right after first paint. It doesn't seem to me what I proposed is useful, though. I wonder if that's still useful as a bandage fix here...
Here is a profile on the quantum ref hardware: https://perfht.ml/2fhfu14

About 4s to first paint the preferences. This is way too slow :-(.

(In reply to Ricky Chien [:rickychien] from comment #12)
> (In reply to Florian Quèze [:florian] [:flo] from comment #9)
> > For 57, we can probably 'hide' the problem or reduce its impact by ensuring the preferences page gets painted at least once before we start initializing the 'Applications' tree.
> 
> Florian, what do you suggest about 'hide' or reduce its impact? Do you know
> any possible approach to lazy initializing the 'Applications' tree? Is it
> probably a quick fix during 57 cycle?

I think a quick way to hide the problem would be to replace the setTimeout at http://searchfox.org/mozilla-central/rev/e76c0fee79a34a3612740b33508276f4b37c3ee8/browser/components/preferences/in-content/main.js#444 with 2 nested requestAnimationFrame calls.

A more real fix would be to avoid main thread IO in the enumerate method from nsHandlerService-json.js, ie make it async. Paolo, do you know if there's already a bug on file for that and/or how much effort it would take to fix it correctly?
Flags: needinfo?(florian) → needinfo?(paolo.mozmail)
(In reply to Florian Quèze [:florian] [:flo] from comment #14)

> I think a quick way to hide the problem would be to replace the setTimeout
> at
> http://searchfox.org/mozilla-central/rev/
> e76c0fee79a34a3612740b33508276f4b37c3ee8/browser/components/preferences/in-
> content/main.js#444 with 2 nested requestAnimationFrame calls.

You don't actually need to wait for a second animation frame,
  window.requestAnimationFrame(() => {
     window.setTimeout(() => {
       this._loadData();
       ...
     }, 0);
  });
should be enough.
I've already seen a significant performance improvement since bug 1375978 landed.

Florian, do you still see 4s of first paint for preferences page? I believe the async font enumerating is able to reduce lots of loading time in your case.
Flags: needinfo?(florian)
(In reply to Ricky Chien [:rickychien] from comment #16)

> Florian, do you still see 4s of first paint for preferences page? I believe
> the async font enumerating is able to reduce lots of loading time in your
> case.

Have you looked at the profiles in comment 0 and comment 14? In my profile at comment 14, font related stuff is 13ms out of the 4s. In the profile from comment 0, it's 30ms out of 4+s.
Flags: needinfo?(florian)
No longer depends on: 1375978
Looks like the problem has been solved with the latest Nightly. The Preferences page now opens swiftly.
(In reply to Kohei Yoshino [:kohei] from comment #18)
> Looks like the problem has been solved with the latest Nightly. The
> Preferences page now opens swiftly.

Was this the first startup after restarting the computer?
Just rebooted macOS and opened Nightly... The same result with no delay. How about you Itiel?
Flags: needinfo?(itiel_yn8)
(In reply to Kohei Yoshino [:kohei] from comment #20)
> Just rebooted macOS and opened Nightly... The same result with no delay. How
> about you Itiel?

All the profiles here (in comment 0 and comment 14) are about Windows. If you were looking at slowness on Mac, it was likely the font issue (bug 1375978) which was very noticeable on Mac.
(In reply to Kohei Yoshino [:kohei] from comment #20)
> Just rebooted macOS and opened Nightly... The same result with no delay. How
> about you Itiel?

Unfortunately no change, so Florian is correct :(
I don't see a major improvement here.
Couldn't attach a profile as it keeps getting stuck at "Waiting for symbol tables for library xul.pdb...".
Flags: needinfo?(itiel_yn8)
OS: Unspecified → Windows
The front-end workaround of comment 15 will be addressed in bug 1400117. I'd like to mark this bug as a meta for tracking both front-end workaround and back-end fix.

Feel free to file a back-end fix and set this as dependency.
No longer blocks: 1400117
Depends on: 1400117
Priority: P2 → --
Summary: Preferences/Options page takes a lot of time to open (3-5 sec), especially on first launch in a session → [meta] Preferences/Options page takes a lot of time to open (3-5 sec), especially on first launch in a session
Depends on: 1400453
(In reply to Itiel from comment #0)
> My machine specs:
> Intel i7-6700, 4GB RAM, 1TB HDD, Windows 10

See Preferences opening test on https://bugzilla.mozilla.org/show_bug.cgi?id=1400117#c3. Our slow references device is obviously slower than above one. But I can't perceive the slowness on our slow references device. This test took roughly 1s to open Preferences at the first time.

Itiel, can you attach the picture of your Preferences "Applications" section? We'd like to know how many app infos are loaded in your browser and perhaps it might be the root cause why it takes too long on your machine.
Flags: needinfo?(itiel_yn8)
[:rickychien] from comment #24)
> (In reply to Itiel from comment #0)
> > My machine specs:
> > Intel i7-6700, 4GB RAM, 1TB HDD, Windows 10
> 
> See Preferences opening test on
> https://bugzilla.mozilla.org/show_bug.cgi?id=1400117#c3. Our slow references
> device is obviously slower than above one. But I can't perceive the slowness
> on our slow references device. This test took roughly 1s to open Preferences
> at the first time.
> 
> Itiel, can you attach the picture of your Preferences "Applications"
> section? We'd like to know how many app infos are loaded in your browser and
> perhaps it might be the root cause why it takes too long on your machine.

I have 38 items in there. I suppose a screenshot wouldn't be of any help as the list is not resizable :)

Not sure why, now the test varies from 0.5 to 1.5 seconds. Tested with Nightly 2017-09-16.
Still can't attach a profile due to the message mentioned in comment 22.
Flags: needinfo?(itiel_yn8)
Here and there the page still takes time to load:
https://perfht.ml/2xr6xMo
I got 8 items on reference machine after fresh installed. I suspect the number of items is the major cause slowing open time, or probably some of those "Applications" items take significant time to initialize. That's why we can't see the slowness of page open when testing in https://bugzilla.mozilla.org/show_bug.cgi?id=1400117#c3.
(In reply to Ricky Chien [:rickychien] from comment #27)
> I got 8 items on reference machine after fresh installed. I suspect the
> number of items is the major cause slowing open time, or probably some of
> those "Applications" items take significant time to initialize. That's why
> we can't see the slowness of page open when testing in
> https://bugzilla.mozilla.org/show_bug.cgi?id=1400117#c3.

I think you're right.  HandlerService.enumerate in nsHandlerService-json.js calls nsIExternalProtocolService.getProtocolHandlerInfo for each scheme, which calls nsOSHelperAppService.GetApplicationDescription, which calls the system API AssocQueryStringW <https://msdn.microsoft.com/en-us/library/windows/desktop/bb773471(v=vs.85).aspx>, which is expensive in the profiles in comment 0 and comment 14.

Probably this is because AssocQueryStringW and friends "cause the overhead of creating and initializing IQueryAssociations each time they are called" <https://msdn.microsoft.com/en-us/library/windows/desktop/bb761400(v=vs.85).aspx>.  The backend fix is presumably to initialize and reuse a single IQueryAssociations pointer when enumerating handlers for schemes.
The profile in comment 14 was with only the 8 default items. There's I/O in there, so the time it takes is random, and potentially very long.
(In reply to Florian Quèze [:florian] [:flo] from comment #14)
> A more real fix would be to avoid main thread IO in the enumerate method
> from nsHandlerService-json.js, ie make it async. Paolo, do you know if
> there's already a bug on file for that and/or how much effort it would take
> to fix it correctly?

No implementation bugs, although there is some background in bug 1287673. As noted in comment 28, the main issue is not with the enumeration itself but with the fact that the underlying Windows API is called on the main thread. I don't know how much effort it would be to move it to a separate thread, but the suggestion from comment 28 might be an easier solution to improve the performance while keeping the call on the main thread.
Flags: needinfo?(paolo.mozmail)
Both front-end and platform implementation are landed, are you still suffering this performance issue when using latest Nightly?
Flags: qe-verify+ → needinfo?(itiel_yn8)
QA Contact: hani.yacoub
Looking much better, and opening it for the second time is almost instantaneous.
Though, interacting with the page (for the first launch) takes a moment or two, but I think this is negligible.
Flags: needinfo?(itiel_yn8)
(In reply to Itiel from comment #32)
> Looking much better

Thanks for checking!

> Though, interacting with the page (for the first launch) takes a moment or
> two, but I think this is negligible.

If you think it's still not as fast as you would like it to be, don't hesitate to attach a new profile.
Before filing this bug I could easily reproduce it anytime, now it hangs when Nightly (with 260~ open tabs, most of them are virtual tabs) is running for long periods of time (2+ days, without opening the Options page in the middle of course) or if the PC is under high load.
For normal uses, opening the Options page feels natural and swift.

I do think there's room for improvement (from a user experience point of view), but attaching a new profile is nerve wracking as you need to wait a (very long) while to get a good "decent" hang from the Options page, and besides, all of my profiles are gibberish for some reason, non are like the one you attached in comment 14 :(
See the attached profile for example (BTW, in this profile I wasn't able to interact with the page for a moment there).
(In reply to Itiel from comment #34)

Thanks!

> all of my profiles are gibberish for some reason, non are like the
> one you attached in comment 14 :(

Instead of "Save as file…" you need to click on "Share". This button is disabled until symbols have been downloaded, so you have to wait a little while (a few seconds to a few minutes depending on your Internet bandwidth and computer speed) before you can click it.

> See the attached profile for example (BTW, in this profile I wasn't able to
> interact with the page for a moment there).

As you mentioned, this profile doesn't have symbols. I can also see that the machine was under heavy load, both in terms of CPU usage (I see thread starvation in the profile) and disk usage (main thread IO takes a long time to complete).

We can also see that the slow stuff involving main thread IO now happens mostly after first paint, so I think this profile is enough to mark as verified bug 1400117.

The interesting part of the profile from comment 35: https://perfht.ml/2hpOvnR

Things worth nothing:
- the nsHandlerService-json.js 'enumerate' call is started from the "pageshow" event listener, and happens right before first paint still :-/. May be a good idea to add a dispatchToMainThread call in there.
- We have slow (~600ms) main thread IO in SHGetFileInfoW while getting icons, at http://searchfox.org/mozilla-central/rev/56ad02e34d0d36ca4d5ccaa885d26aff270b8ff7/image/decoders/icon/win/nsIconChannel.cpp#413 This seems to be bug 827440.
- We have more slow (~360ms) main thread IO while getting the display name of default application handlers, at http://searchfox.org/mozilla-central/rev/56ad02e34d0d36ca4d5ccaa885d26aff270b8ff7/browser/components/preferences/in-content/main.js#2630
- initializing Sync takes about 110ms here, mostly loading all the dependent modules. I wonder if all of this is really needed. I guess this should be investigated in a separate bug in the Sync component.
Close this meta bug since both dependencies have been fixed already.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 57
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: