1651434 - Tab loading takes a very long time after a new startup or a restart

Status: NEW

(WebExtensions :: General, defect, P3)

Description

[AndreL]

Attachment: Firefox 2020-07-08 18.34 profile.json.gz

Steps to reproduce:

• Start Firefox or Restart to install an update.

Actual Result:

• All tabs (both pin and current) take 2-4mins to load without any activity during that time.

Expected Result:

• All tabs should have start loading normally.

Extra info:
For some reason going to Devtool network tab during load or record a profile speeds up the process a bit, at least during the creation of the record in attachment the tabs ended up loading much faster.

Comment 1

[AndreL]

Attachment: About:Support

The profile was recorded immediately after startup until the first tab loaded.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

The profile from comment one published https://share.firefox.dev/338qx6l

Comment 3

[Olli Pettay [:smaug][[e-mail]]]

Extension process is very busy. Reporter, is the performance better if you disable uBlock?

Comment 4

[AndreL]

Unfortunately i can't test this anymore.

Before, cleaning the cache would solve it temporarily and enabling the 'about:home startup cache' experiment when it came out fixed this problem and has since gotten proggresively better. Now even if i disable it i don't get the reported problem so i can't test it further. I think this bug can be closed.

Comment 5

[[e-mail]]

Extension process is very busy.

By the look of it, it's as if uBO was not able to fetch its filter list data from its IndexedDB database and in such case it was forced to download many lists from remote servers, and once these lists were downloaded, it has to parse and compile them. Typically these steps do not occur when uBO is launched except at the very first install -- but this obviously was not a first install. So my guess is that uBO's read operations from its IndexedDB were failing for whatever reason.

Another side issue is the selection of filter lists, OP should remove the following lists from Custom section:

• Adblock Warning Removal List: not needed in uBO
• Both malware lists -- they were dropped by uBO as not being maintained

Also, I see many lists are pulled from the gitcdn.xyz server and this server has been unreliable, though this should not be really an issue when uBO's IndexedDB works fine -- which I think is the issue in the profiling results, this causes uBO to spend ~4 second downloading/parsing/compiling many filter lists, then ~1 second loading the resulting compiled filters in memory. Typically, users will launch uBO with a valid memory snapshot stored in the IndexedDB so load time would be a fraction of what I see in these profiling results, i.e. ~0.5 second.

In any case, beside the abnormal way uBO had to launch, as if it was a first time installation, uBO is ready before the 14-second mark, so I don't see it being involved in delaying the loading of web pages beyond the the 14-second mark.

Comment 6

[Rob Wu [:robwu]]

5.7 seconds spent on localStorage.removeItem
3.5 seconds spent in initialization of uBlock Origin.
https://share.firefox.dev/33vZBxK

Luca wanted to look into the time spent in localStorage, as he recalled some related bug.

EDIT: and as seen in the "Marker Chart" section of the "Parent Process" row, the request is suspended and awaiting uBlock Origin: https://share.firefox.dev/2C9tVTG

Comment 7

[[e-mail]]

3.5 seconds spent in initialization of uBlock Origin.

My comment above applies pretty much as well to these profiling results:

• uBO is misconfigured -- it has a selection of lists which should not be used in uBO
• uBO's indexedDB seems to not be in used or is being unduly wiped

The selection of lists tells me this is not a first launch after install, meaning the lists should have already been downloaded and stored in uBO's indexedDB storage, but the profiling results show that nothing could be fetched from the indexedDB storage and as a consequence all lists not part of the extension package have to be downloaded/parsed/compiled -- this is time consuming.

Comment 8

[Mike Conley (:mconley) (:⚙️)]

If anybody is still able to reproduce this, it'd be great if we could also profile the BGIOThreadPool thread as well.

Comment 9

[Luca Greco [:rpl] [:luca] [:lgreco]]

Re-assign a needinfo to me to investigate this (as I cleared it by mistake)

Comment 10

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hi AndreL,
do you still have the original Firefox profile from which you collected the profiling data?
(it doesn't need to still reproduce the slow startup, I'm only interested in which addon were installed, to be able to identify one that seems to be slowing down the WebExtensions child process during the startup)

could you look in about:debugging which is the extension with the "Internal UUID" 41005d28-4fd7-4f7a-89fc-c279c499c8c1?
is it ublock itself or one of the other extension installed?

Comment 11

[Luca Greco [:rpl] [:luca] [:lgreco]]

I took another look to the profiles attached and looking to this marker chart related to the WebExtensions child process:

• https://share.firefox.dev/34Eorud

it seems that a good chunk of the extension process startup time was blocked on a background script execution from an extension with the "internal UUID" 41005d28-4fd7-4f7a-89fc-c279c499c8c1

Looking to the stack chart (https://share.firefox.dev/3ny8P49) it looks that the script execution is blocking the WebExtensions child process main thread when it does call the window.localStorage.remove WebAPI method, which seems to synchronously waiting for LSObject::EnsureDatabase to complete.

I've been trying to recreate the slow startup time by trying to recreate the conditions of a "broken Quota Manager Service initialization", but I'm still unable to get a slow startup similar to the one in the profiles attached to this issue:

• "breaking" the "QuotaManager service initialization" seems to have the opposite effect, ublock and the other extensions get errors on calling browser.storage.local methods and the first page does actually load immediately, but without any ad blocking
• I think that a slow "Quota Manager Service initialization" may instead trigger a slow startup but I'm not sure that it is what the profiles linked are actually showing

Comment 12

[gwarser]

uBO has own background page, so it does not use "_generated_background_page.html"?

Comment 13

[Luca Greco [:rpl] [:luca] [:lgreco]]

(In reply to gwarser from comment #12)

uBO has own background page, so it does not use "_generated_background_page.html"?

good point, that should exclude uBO as I was assuming and it likely means that uBO may have kept the first page load suspended as a side effect of not being able to execute anything until that script from another of the installed extension was fully executed (and the WebExtensions process was finally able to let uBO to do its work and unblock the suspended request).

Comment 14

[[e-mail]]

The removeItem call is from Nano Defender, see https://github.com/jspenguin2017/uBlockProtector/blob/d5534f8abe4eff1845b2dfe53e6a4079f9ce4d43/src/background/core.js#L205.

It's called unconditionally at extension launch, since hasNews is always false.

The call tree shows the extension uuid:

Extension Nano Defender" (ID: {fcf60470-b210-4c17-969e-9ae01491071e}): moz-extension://41005d28-4fd7-4f7a-89fc-c279c499c8c1/background/core.js:340:61

Comment 15

[stephen.murphy]

Hi All,

I can reproduce this behaviour every time. For me, 2-4 mins would be quick after FF restart. I am using FF 99 on Ubuntu 20.04 LTS. I have had this issue for a long time and work around it by not closing FF and suspending the machine. I have an old I7 (4th gen), 16GB RAM, SSD system disk a magnetic user data disk. FF profile is on the magnetic.

Steps to reproduce:

1. Close FF completely
2. Reopen FF
3. Tabs start to reload and are blank or have spinning icon for many minutes. New tabs the same, but seem to be slightly quicker to become usable.
4. Wait many minutes - tabs usable.

Creating a new profile does speed things up, but the huge delay comes back again after a couple of uses of the new profile.

Found a post that suggested deleting <profile>/datareporting/archived directory which others reported 'cured' the problem. For me, this seems to knock a few minutes off the time it takes for FF to be usable, but it's no miracle cure, it still takes many minutes.

Happy to run tests etc. if it helps.

Thanks.

Steve

Comment 16

[BugBot [:suhaib / :marco/ :calixte]]

The bug has a release status flag that shows some version of Firefox is affected, thus it will be considered confirmed.

Comment 17

[BugBot [:suhaib / :marco/ :calixte]]

Redirect a needinfo that is pending on an inactive user to the triage owner.
:mixedpuppy, since the bug has recent activity, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 18

[Robin Whittleton]

I’ve had this for a while, finally read through this bug and can confirm that deleting <profile>/datareporting/archived gets this back to normal. I don’t use uBO so that’s certainly not required for this bug. I only had 9 files files in there, of a maximum of 33KB in size, so whatever the problem is it doesn’t feel like it’s about parsing a large pile of data.

Comment 19

[Bas Schouten (:bas.schouten)]

The Performance Impact Calculator has determined this bug's performance impact to be low. If you'd like to request re-triage, you can reset the Performance Impact flag to "?" or needinfo the triage sheriff.

Platforms: [x] Windows [x] Linux
Impact on browser: Renders browser effectively unusable
Configuration: Specific but common
Websites affected: Rare
[x] Multiple reporters