Very slow session restore (profile included)
Categories
(WebExtensions :: General, defect)
Tracking
(Performance Impact:medium, firefox75 affected)
People
(Reporter: yoasif, Unassigned)
Details
(Keywords: perf:frontend, perf:startup)
Attachments
(4 files, 1 obsolete file)
Basic information
I have a Firefox profile that has a few extensions in Linux that is markedly slower to start up in Linux than in Windows with a similar setup.
I don't know why that is, so I recorded a profile.
More information
Profile URL: https://drive.google.com/open?id=1P6avNt-oy-LAOk4H19DOmlJUz9pdBiai
Basic systems configuration:
OS version: Ubuntu 20.04
GPU model: Intel(R) HD Graphics 630 (KBL GT2)
Number of cores: 4
Amount of memory (RAM): 24GB
Thanks so much for your help.
Reporter | ||
Comment 1•4 years ago
|
||
Comment 2•4 years ago
|
||
WebExtensions process is taking lots of time
Comment 3•4 years ago
|
||
There are a ton of extensions installed here:
Reddit Enhancement Suite
Tab Counter Plus
Duplicate Tabs Closer
Ebay Container
ClearURLs
Firefox Pioneer
Bitwarden - Free Password Manager
Google Container
First Party Isolation
Extension source viewer
Page Translator Revised
Twitter Container
Display #Anchors
uBlock Origin
LinkedIn Container
Reddit (Au) Comment Highlights
Amazon Container
Always Right
enhanced-h264ify
Forget Me Not - Forget cookies & other data
Forget Me Not and Bitwarden in particular execute a lot of code in that profile. Just to help narrow this down, can you compare the time to do a session restore in that profile with those two extensions disabled?
Reporter | ||
Comment 4•4 years ago
|
||
Andrew, it is better with those two extensions disabled https://drive.google.com/open?id=17EpH3FwpiFAKwE29jxlErStsncOZvH4I
One thing I will note (and the reason I opened this bug) is because I run a very similar profile on my Windows dual boot (so same hardware), and Firefox opens up within seconds using the same session restore file.
There is something weird going on in Linux and I figured that was worth exploring.
Comment 5•4 years ago
|
||
Since you're claiming a significant difference in behavior between Windows and Linux, could you provide the profiles for both Windows and Linux? And please share it with perf-html.io link instead of Google Drive.
Comment 6•4 years ago
•
|
||
And please share it with perf-html.io link instead of Google Drive.
PSA: pref-html.io has moved to profiler.firefox.com
Reporter | ||
Comment 7•4 years ago
|
||
I can't upload these to profiler.firefox.com - it fails when I try.
Comment 8•4 years ago
|
||
Florian, what information is useful for diagnosing failures uploading profiles (see comment 7)?
Reporter | ||
Comment 9•4 years ago
|
||
I had some trouble grabbing this profile (had to reduce the startup entries because the profiler didn't pick up the profile when trying to grab it).
https://drive.google.com/open?id=1v-fJKCFO4aPmIJEstR_39FMLICgLgzrS
Once again, this failed uploading to profiler.firefox.com
Comment 10•4 years ago
|
||
Looks like the profiler.firefox.com upload failures are simply 413 (request too large)
The extension process is certainly doing a lot of work in the Linux profile, but I'm not sure that explains the extremely long delays all the outgoing web requests are experiencing (including those that are served from the cache). This session includes uBlock Origin, but from eyeballing, it doesn't look like the extension process is so bogged down that uBO can't act on web requests for the 60 seconds (!!) that many initial requests are delayed for.
Adding fxperf to get some more experienced profile-analyzing eyes on this.
Comment 11•4 years ago
|
||
(In reply to Andrew Swan [:aswan] from comment #10)
Looks like the profiler.firefox.com upload failures are simply 413 (request too large)
Yes, the upload failures are just the profiles being too large.
It's possible upload subsets of the profile though. Eg. https://perfht.ml/2IL3x1W shows the main thread I/O we do in the profile from comment 9 when killing unresponsive content processes.
Comment 12•4 years ago
|
||
There's many hundreds of setTimeout calls here in pid 3820, all seeming to come from BitWarden. Don't know if I can get the source in any way to make that make sense. It goes through browserActionSetBadgeText
, then crypto_service_awaiter
. I don't think that the setTimeouts themselves are responsible for the slowness, but I would certainly bet that they are indicative of something going terribly wrong inside BitWarden which is likely responsible for the slowness.
Comment 13•4 years ago
|
||
(In reply to Doug Thayer [:dthayer] from comment #12)
There's many hundreds of setTimeout calls here in pid 3820, all seeming to come from BitWarden.
...
I don't think that the setTimeouts themselves are responsible for the slowness, but I would certainly bet that they are indicative of something going terribly wrong inside BitWarden which is likely responsible for the slowness.
Comment 4 includes a profile without bitwarden. Content loads are still taking a very long time. There's still a fair amount of activity in the extension process, but that process isn't pegged at 100% even when content loads are not finishing. It does look like a lot of content processes are exiting (crashing?) in that profile.
Don't know if I can get the source in any way to make that make sense.
I don't think extensions are the issue here but for posterity, you can browse the actual contents that run in the browser here: https://robwu.nl/crxviewer/?crx=https%3A%2F%2Faddons.mozilla.org%2Ffirefox%2Fdownloads%2Ffile%2F3526255%2Fbitwarden_free_password_manager-1.43.3-an%2Bfx.xpi%3Fsrc%3Dsearch
But in this case, the background page alone is 5 MB of webpacked stuff. It is built from https://github.com/bitwarden/browser, that might be easier to read.
Comment 14•4 years ago
|
||
I was more just hopeful that the excessive setTimeout time would point to something weird going on. In the profile from comment 4, there's still almost a 60 second window in the WebExtensions process dominated by setTimeout. Is it just normal for extensions to rely on setTimeout for things such that it dominates their startup profile? Feels weird. The Windows profile is also less dominated by setTimeout calls, though they still represent an alarmingly large portion of things.
Comment 15•4 years ago
|
||
The priority flag is not set for this bug.
:mixedpuppy, could you have a look please?
For more information, please visit auto_nag documentation.
Comment 16•4 years ago
|
||
One thing I'll note is that launching each of the content processes seems to take over 200ms each on the Linux machine:
It looks like most of the time is spent scanning fonts?
Compare that to the launching time on Windows:
Does any of this look familiar, jfkthame?
Comment 17•4 years ago
|
||
It seems to be spending an unexpectedly-huge amount of time in the parent under ReadSystemFontList, which is supposed to serialize the list of available fonts to pass to the new process. It's not surprising this is called, but it does surprise me to see it take ~200ms... I just profiled a launch here and saw more like 13ms there. I have no idea why it'd be taking so long on the reporter's system.
Comment 18•4 years ago
|
||
Hi Asif,
How many fonts do you have installed on your system, out of curiosity? Also, do you have any AV software installed and enabled?
I'll also notice that in the profile, it looks like there are multiple windows here... Asif, how many windows do you tend to have open?
Reporter | ||
Comment 19•4 years ago
•
|
||
Mike, I have 16 windows open right now, one of which is a SSB which isn't restored on startup (kinda wish it did). This is fairly normal for me, and FWIW it is the same setup I had on Windows when I took the corresponding profile (reused my sessionstore file).
fc-list | wc -l
comes back with 2870 which is kind of surprising to me, while locally installed fonts alone (fc-list|grep -i .local | wc -l
) comes out to 332.
I have gone ahead and attached my fc-list output to the bug. I'm not sure how unusual this is - most of the fonts seem to be in the "Noto" family (2148!).
Also, no antivirus.
Comment 20•4 years ago
|
||
Does the fc-list
data from comment #19 explain why the font initialization would be slow?
Also, is there a project tracking sharing the font list? Because from the profile, it looks like we pay this cost for the parent, the 8 child processes, then the webextension process, etc. Would be great if we could avoid that...
Comment 21•4 years ago
|
||
Yes, there's work in progress to share the list, which ought to help here; see bug 1533462 and dependencies etc.
Asif's system does have a lot more fonts installed than my Linux box has, so it's not really comparable; I'll try installing a bunch of additional font packages and see how badly it slows down.
Reporter | ||
Comment 22•4 years ago
|
||
Jonathan, if you are on an Ubuntu system, I think fonts-noto
will get you most of the way there.
Comment 23•4 years ago
|
||
On ubuntu 18.04 (my main Linux machine), fonts-noto only installs a few hundred fonts, nothing like your big list.
I also have a VM with 20.04, but am currently having some trouble with its setup.... maybe time to reinstall.
Reporter | ||
Comment 24•4 years ago
•
|
||
On my end fonts-noto
pulls in fonts-noto-core fonts-noto-extra fonts-noto-ui-core fonts-noto-ui-extra fonts-noto-unhinted
as well.
sudo apt install fonts-noto
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following additional packages will be installed:
fonts-noto-core fonts-noto-extra fonts-noto-ui-core fonts-noto-ui-extra fonts-noto-unhinted
The following NEW packages will be installed:
fonts-noto fonts-noto-core fonts-noto-extra fonts-noto-ui-core fonts-noto-ui-extra fonts-noto-unhinted
0 upgraded, 6 newly installed, 0 to remove and 18 not upgraded.
Need to get 93.1 MB of archives.
After this operation, 435 MB of additional disk space will be used.
Comment 25•4 years ago
|
||
OK, I reinstalled my 20.04 VM and was then able to install fonts-noto (and its dependencies), which gives me a fc-list | wc -l
count of 2489; not quite as high, but ought to be enough to be broadly similar.
Two things puzzle me here. First, I'm still not seeing anything like as much time under gfxFcPlatformFontList::ReadSystemFontList
in the parent process; your profile shows around 150-200ms there for each child process launch, whereas I'm only seeing tens of ms.
The other thing that bothers me is that the profile seems to show ReadSystemFontList calling the fontconfig function FcNameParse
. That makes no sense, AFAICS; ReadSystemFontList uses FcNameUnparse, but not Parse. And my local profile indeed shows it calling the Unparse APIs, and not FcNameParse.
So there's something weird going on in your system, but I have no idea what. :(
Updated•4 years ago
|
Reporter | ||
Comment 26•4 years ago
|
||
Based on feedback from Mike Conley, I went ahead and captured another profile without any apps open on my machine - I just logged out, logged in and captured a profile of my session restore. I was unable to upload it using the profiler, so you can download it here: https://drive.google.com/open?id=1TsD7AdllL-6kYn6jUM3BEk2NTEHC6-PY
Thanks!
Comment 27•4 years ago
|
||
(In reply to Asif Youssuff from comment #26)
Thanks!
I was unable to upload it using the profiler, so you can download it here: https://drive.google.com/open?id=1TsD7AdllL-6kYn6jUM3BEk2NTEHC6-PY
If we keep only the parent process and the WebExtension process, it becomes small enough to upload: https://perfht.ml/3aZR86E
Comment 28•4 years ago
|
||
Additional information from the reporter - their Linux box is encrypted using LUKS on a "f2fs" filesystem.
Comment 29•4 years ago
|
||
Hey stransky, are you familiar with LUKS? Have you heard anything about users experiencing sluggish Firefox startup with LUKS enabled?
Reporter | ||
Comment 30•4 years ago
|
||
Given that you may suspect that my filesystem may be at issue here, I went ahead and copied my Firefox profile to a RAM disk to see whether it was any faster.
That profile is here: https://drive.google.com/open?id=1j5x0kMyJZU1mfcoptKsWHDiD_mam7X5n
I created a ram disk using mkdir -m0700 /dev/shm/firefox
and symlinked that directory to the name of my original Firefox profile, then copied the files from my original profile to the symlinked directory.
Comment 31•4 years ago
|
||
Bizarre - the font reads, for example, are still excessive. Does this RAM disk use the LUKS encryption?
Reporter | ||
Comment 32•4 years ago
•
|
||
Mike, no -- it is just a straight up RAM disk that I created as I mentioned above - I don't think I did anything wrong in creating it.
There are a couple of more avenues for exploration if you think this is a more core problem to my system - I am using the "xanmod" kernel that is supposed to be optimized for end user speed (less server, more desktop) - I can try removing that.
Also, the Firefox binary was not located on the RAM disk, but I really don't see how that would make much of a difference.
Lastly, I am using "oibaf" bleeding edge graphics drivers on my machine from the latest upstream mesa. That may be causing issues. I can undo both the kernel and the mesa updates and profile again on the RAM disk.
Is it worth putting the Firefox binary on the RAM disk as well?
Comment 33•4 years ago
•
|
||
Okay, that seems like strong evidence that the file system is unrelated then. I guess we can cross that off the list!
Well, maybe I spoke too soon. Only the user profile went onto the RAM disk. There are likely plenty of other resources being read from disk that aren't from the user profile.
Comment 34•4 years ago
|
||
Putting the needinfo back on stransky just in case he's aware of anything related to LUKS that might resemble what we're seeing here.
Reporter | ||
Comment 35•4 years ago
•
|
||
Recorded a profile using perf
. The file is a little too large for bugzilla, grab it from https://drive.google.com/open?id=1O0Bdm2hJ9C0G4QyswSRF6AlMRuYBCOmx
I also converted it to text, per https://github.com/firefox-devtools/profiler/blob/master/docs-user/guide-perf-profiling.md
https://drive.google.com/open?id=1QZEYMvEUMqIO6EY9FRm8x6SHs-wGOFAh
Made some changes since my last profile. No longer running the xanmod kernel, nor am I running the latest mesa code. I reverted both of those to the stock Ubuntu packages.
Reporter | ||
Comment 36•4 years ago
•
|
||
Took a new profile using the instructions on https://github.com/firefox-devtools/profiler/blob/master/docs-user/guide-perf-profiling.md (enabled -g
for example):
https://drive.google.com/open?id=1vszMPbfgk5p3vicZcT5FXIU883ELnObH
Comment 37•4 years ago
•
|
||
The perf profile in comment 36 works for me, thanks Asif.
This is really interesting. This looks like pretty different behaviour compared to when running with the Gecko Profiler. For example:
- Launching processes doesn't take nearly as long
- The WebExtension process seems to have very few samples during the first 10 or so seconds of its process lifetime. I'm not sure if that means its not getting serviced, the sampling thread isn't getting serviced, or if that thread is idle.
Comment 38•4 years ago
|
||
Hey jesup, you're more well-versed, I think, at reading perf
profiles than I am. The WebExtension process (Process 12033), seems to do very little during the first 10 seconds of its life. Is that because it's not getting CPU time, or the sampler isn't getting CPU time, or does it mean that the thread is idle?
It's also unfortunate that I can't seem to Publish this profile, despite the fact that it seems to compress nicely. :(
Comment 40•4 years ago
|
||
(In reply to Mike Conley (:mconley) (:⚙️) from comment #33)
Okay, that seems like strong evidence that the file system is unrelated then. I guess we can cross that off the list!Well, maybe I spoke too soon. Only the user profile went onto the RAM disk. There are likely plenty of other resources being read from disk that aren't from the user profile.
In particular, presumably all the user's installed fonts are still on the encrypted disk.
But I still don't understand at all why the parent process, when launching a child, is spending all that time calling FcNameParse
(comment 25). That doesn't make any sense -- unless the reporter's symbols are wrong for the fontconfig library?
Comment 41•4 years ago
•
|
||
I used this tool to measure the performance:
https://askubuntu.com/questions/87035/how-to-check-hard-disk-performance
and I tested luks/regular partition, both on SSD drive. luks partition gives me 1GB/s read speed and regular partition gives me 2GB/s read speed. So there's definitely a difference here.
Comment 42•4 years ago
|
||
Asif, can you try the benchmark from https://askubuntu.com/questions/87035/how-to-check-hard-disk-performance ? The tool is named "Disks" on Fedora (and maybe on some later Ubuntu too).
Updated•4 years ago
|
Comment 44•4 years ago
|
||
(In reply to Asif Youssuff from comment #43)
Benchmark attached.
Is that really the luks file system? Looks like a regular one to me. You should run the test on a particular partition, not on the device itself.
Reporter | ||
Comment 45•4 years ago
|
||
Benchmark attached; didn't realize I could benchmark the LUKS block device, so redid the old benchmark.
Reporter | ||
Comment 46•4 years ago
|
||
Also attaching my root partition in case that was relevant (I have a separate home).
Comment 47•4 years ago
|
||
That looks fast enough to me....
Comment 48•4 years ago
|
||
(In reply to Mike Conley (:mconley) (:⚙️) from comment #38)
Hey jesup, you're more well-versed, I think, at reading
perf
profiles than I am. The WebExtension process (Process 12033), seems to do very little during the first 10 seconds of its life. Is that because it's not getting CPU time, or the sampler isn't getting CPU time, or does it mean that the thread is idle?
The webextension process was also mostly idle for the first 17s on the profile from the gecko profiler: https://perfht.ml/3aZR86E
It's also unfortunate that I can't seem to Publish this profile, despite the fact that it seems to compress nicely. :(
Comment 49•4 years ago
|
||
fxperf:p2 while we're still figuring this out, we can re-evaluate once we've figured out a/the/some culprit(s).
Comment 50•4 years ago
|
||
The thread is idle during that time; the master process mainthread is pretty busy (~70%?), but you have multiple cores I presume. Also if a thread is running-but-suspended, it will show as running in perf, and it's not being shown as running in the webextensions process
Updated•2 years ago
|
Updated•1 year ago
|
Description
•