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)
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.
Comment 1•7 years ago
|
||
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
Comment 2•7 years ago
|
||
[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.
status-firefox55:
--- → unaffected
status-firefox56:
--- → affected
status-firefox57:
--- → affected
tracking-firefox56:
--- → ?
tracking-firefox57:
--- → ?
Comment 3•7 years ago
|
||
Track 56+/57+ as performance impact. Hi Ricky, Is this issue under your coverage?
Updated•7 years ago
|
Flags: needinfo?(rchien)
Whiteboard: [photon-preference][triage]
Updated•7 years ago
|
Blocks: photon-preference
Comment 4•7 years ago
|
||
According to Font Book, I have 561 fonts now on my MacBook Pro.
Comment 5•7 years ago
|
||
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?
Comment 7•7 years ago
|
||
(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.
Comment 8•7 years ago
|
||
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)
Comment 9•7 years ago
|
||
(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)
Comment 10•7 years ago
|
||
Thanks, that seems clear. I agree it is too late to focus on this for 56 if there isn't a quick fix.
Comment 11•7 years ago
|
||
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
Comment 12•7 years ago
|
||
(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)
Updated•7 years ago
|
Flags: qe-verify+
Priority: -- → P2
QA Contact: hani.yacoub
Whiteboard: [photon-preference][triage] → [photon-preference]
Comment 13•7 years ago
|
||
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...
Comment 14•7 years ago
|
||
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)
Comment 15•7 years ago
|
||
(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.
Comment 16•7 years ago
|
||
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)
Comment 17•7 years ago
|
||
(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)
Comment 18•7 years ago
|
||
Looks like the problem has been solved with the latest Nightly. The Preferences page now opens swiftly.
Comment 19•7 years ago
|
||
(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?
Comment 20•7 years ago
|
||
Just rebooted macOS and opened Nightly... The same result with no delay. How about you Itiel?
Flags: needinfo?(itiel_yn8)
Comment 21•7 years ago
|
||
(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.
Reporter | ||
Comment 22•7 years ago
|
||
(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)
Updated•7 years ago
|
OS: Unspecified → Windows
Comment 23•7 years ago
|
||
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.
Comment 24•7 years ago
|
||
(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)
Reporter | ||
Comment 25•7 years ago
|
||
[: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)
Reporter | ||
Comment 26•7 years ago
|
||
Here and there the page still takes time to load: https://perfht.ml/2xr6xMo
Comment 27•7 years ago
|
||
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.
Comment 28•7 years ago
|
||
(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.
Comment 29•7 years ago
|
||
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.
Comment 30•7 years ago
|
||
(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)
Comment 31•7 years ago
|
||
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
Reporter | ||
Comment 32•7 years ago
|
||
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)
Comment 33•7 years ago
|
||
(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.
Reporter | ||
Comment 34•7 years ago
|
||
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).
Reporter | ||
Comment 35•7 years ago
|
||
Reporter | ||
Comment 36•7 years ago
|
||
Comment 37•7 years ago
|
||
(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.
Comment 38•7 years ago
|
||
Close this meta bug since both dependencies have been fixed already.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Updated•7 years ago
|
status-firefox-esr52:
--- → unaffected
Target Milestone: --- → Firefox 57
You need to log in
before you can comment on or make changes to this bug.
Description
•