1871797 - Long loading times (tab loading indicator continues to spin; tabswitching spinner when switching tabs) when trying to browse the web

Status: RESOLVED WORKSFORME

(Application Services :: Webext Storage, defect, P2)

Description

[klebbutdifferent]

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36

Steps to reproduce:

I opened firefox and proceded to open a few websites and made sure no Add-ons weren't enabled.
I opened Firefox andproceeded to open a few websites, making sure that no add-ons were enabled. This bug has been occurring to me quite frequently for a few years, but I finally got around to reporting it. The reason for ensuring that no add-ons were enabled is that the last time I posted this bug the Add-ons were blamed for breaking Firefox then the case was closed. The video below will prove that this isn't the case.

This is my current user agent string: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0

Actual results:

The pages simply didn't load at all.

Here's a video (From october but the issue still persists and happens the same way so that's why i'm posting this).
https://youtu.be/XzdZ1etb23g

Expected results:

It simply should not take more than three minutes to load a page.

Comment 1

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

The Bugbug bot thinks this bug should belong to the 'Core::Audio/Video: Playback' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Comment 2

[:Gijs (he/him)]

Are there errors in the browser console when this happens (open with Ctrl-Shift-J -- not the regular developer console), and do you know if this works on a clean Firefox profile? (you can keep your existing profile, but this would help eliminate effects from settings or other brokenness)

Comment 3

[David Chmelik]

I have same problem in recent FireFox versions for a month or two... all tabs (even 127.0.0.1) were taking 10+mins to load, but now I don't even know how long, while other web browsers don't have this problem. They finally all (barely over 30 tabs) loaded after maybe half an hour or 45mins (in superior older versions with tab groups, I had 100+ tabs load in a minute or two).

Comment 4

[klebbutdifferent]

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

Are there errors in the browser console when this happens (open with Ctrl-Shift-J -- not the regular developer console), and do you know if this works on a clean Firefox profile? (you can keep your existing profile, but this would help eliminate effects from settings or other brokenness)

I will test both things and will return with results, as soon as i can as it's not something that happens 100% percent of the time.

Comment 5

[klebbutdifferent]

I come back to fillthe needinfo request

(console with extensions disabled) https://youtu.be/9GkX3ZGctZY
(console with extensions enabled) https://youtu.be/-jxdIWVnuS4
(console screenshot after the pages loaded with extensions enabled) https://media.discordapp.net/attachments/573226542801616899/1193391507907039323/image.png?ex=65ac8b73&is=659a1673&hm=a9d0593163342122292931b03349a4f514e352222d136d7b2e15b2918f6be07b&=&format=webp&quality=lossless&width=719&height=370

And no the issue doesn't happen on a clean profile and by the way i'm typing this from the clean profile while the old one struggles to load a page in the background

Comment 6

[:Gijs (he/him)]

(In reply to David Chmelik from comment #3)

I have same problem in recent FireFox versions for a month or two... all tabs (even 127.0.0.1) were taking 10+mins to load, but now I don't even know how long, while other web browsers don't have this problem. They finally all (barely over 30 tabs) loaded after maybe half an hour or 45mins (in superior older versions with tab groups, I had 100+ tabs load in a minute or two).

Is this reproducible every time? comment #4 suggests it's intermittent for the original reporter. If you see this every time, it would be very useful to check with mozregression what exact change broke things for you.

(In reply to klebbutdifferent from comment #5)

I come back to fillthe needinfo request

Thanks, this is helpful. Something is getting confused when loading tabs there, as we end up hitting this bit of code, which means we don't remove the "pending" attribute which somewhat explains why the new tab page never loads properly (even though it's visible etc.). But the root cause is probably whatever is causing this confusion, as I'm not sure why the tab wouldn't be interactive when loading pages otherwise. Unfortunately it's not clear to me off-hand what that could be; there aren't obvious clues in the error logs that I can see.

Could you attach a copy of your about:support information from the profile that has this issue?

Comment 7

[klebbutdifferent]

Attachment: About support info requested by Gijs as code.

Comment 8

[klebbutdifferent]

Attachment: About support info requested by Gijs as text.

Comment 9

[David Chmelik]

In reply, it's apparently not happening for me every time. If I test in future will there be a mozregression addon/extension/plugin?

Comment 10

[Niklas Baumgardner [:niklas]]

Thanks for filing this bug. We didn't see anything obvious from the about:support information.

Could you use the Firefox profiler and send us a profile of the behavior? The docs for the Firefox profiler can be found here.

Comment 11

[klebbutdifferent]

(In reply to Niklas Baumgardner [:niklas] from comment #10)

Thanks for filing this bug. We didn't see anything obvious from the about:support information.

Could you use the Firefox profiler and send us a profile of the behavior? The docs for the Firefox profiler can be found here.

Here's a google drive folder with 2 profiles one from yesterday and one from today
https://drive.google.com/drive/folders/1TkYziakx_Wi6cKnECtToaG9q1z3Mp7PA?usp=sharing

Comment 12

[klebbutdifferent]

(In reply to klebbutdifferent from comment #11)

(In reply to Niklas Baumgardner [:niklas] from comment #10)

Thanks for filing this bug. We didn't see anything obvious from the about:support information.

Could you use the Firefox profiler and send us a profile of the behavior? The docs for the Firefox profiler can be found here.

Here's a google drive folder with 2 profiles one from yesterday and one from today
https://drive.google.com/drive/folders/1TkYziakx_Wi6cKnECtToaG9q1z3Mp7PA?usp=sharing

Added another profile from today

Comment 13

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

The severity field is not set for this bug.
:mossop, could you have a look please?

For more information, please visit BugBot documentation.

Comment 14

[:Gijs (he/him)]

Making sure we see this in triage tomorrow.

Comment 15

[:Gijs (he/him)]

Thanks. These profiles combined with the recordings are pretty confusing. The network loads are taking a super long time (many minutes), but unfortunately the profiles themselves don't have super clear pointers (at least as far as I can see) as to why they take this long. One thing I did note is that in the first profile (in the top profile / 13.6MB - Firefox 2024-01-12 22.16), the profiler indicates for some loads that it's waiting 60s for a socket thread. I don't know why we'd run out of those / why there would be a problem getting to those threads. Valentin, do you know more about this / do you have suggestions on how to debug further?

(as an aside: do we have telemetry for the time we wait for socket threads that we could use to establish how frequent this is / if there are pathological edgecases / make sure the number of threads etc. is right?)

A bit of a wild guess, but I wonder if, if you run without extensions and revert the preferences:

network.predictor.enabled
network.prefetch-next
network.http.speculative-parallel-limit
network.dns.disablePrefetch

in about:config, if then the problem goes away?

It looks like these preferences can be set by an extension, but I expect that they stay enabled if the extension is disabled (though I could be wrong about this).

In one of the profiles, the webextension storage database is loaded synchronously and this takes a full 10 seconds on startup. Luca, is this normal? (in the top profile / 13.6MB - Firefox 2024-01-12 22.16)

Comment 16

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

Hi Gijs,
based on a quick look to the first and last profile I'm assuming that for webextension storage database you mean the webext_storage_bridge which is part of the storage.sync rust based backend.

Hi Mark, would you mind to take a look at the profile to provide your perspective about what may be going on and how we may followup to investigate further and/or plan to fix this issue?

The issue can be easily be found by clicking on the bigger jank bar in the main process.

Comment 17

[klebbutdifferent]

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

Thanks. These profiles combined with the recordings are pretty confusing. The network loads are taking a super long time (many minutes), but unfortunately the profiles themselves don't have super clear pointers (at least as far as I can see) as to why they take this long. One thing I did note is that in the first profile (in the top profile / 13.6MB - Firefox 2024-01-12 22.16), the profiler indicates for some loads that it's waiting 60s for a socket thread. I don't know why we'd run out of those / why there would be a problem getting to those threads. Valentin, do you know more about this / do you have suggestions on how to debug further?

(as an aside: do we have telemetry for the time we wait for socket threads that we could use to establish how frequent this is / if there are pathological edgecases / make sure the number of threads etc. is right?)

A bit of a wild guess, but I wonder if, if you run without extensions and revert the preferences:

network.predictor.enabled
network.prefetch-next
network.http.speculative-parallel-limit
network.dns.disablePrefetch

in about:config, if then the problem goes away?

It looks like these preferences can be set by an extension, but I expect that they stay enabled if the extension is disabled (though I could be wrong about this).

In one of the profiles, the webextension storage database is loaded synchronously and this takes a full 10 seconds on startup. Luca, is this normal? (in the top profile / 13.6MB - Firefox 2024-01-12 22.16)

I did that and it still happened(In reply to :Gijs (he/him) from comment #15)

Thanks. These profiles combined with the recordings are pretty confusing. The network loads are taking a super long time (many minutes), but unfortunately the profiles themselves don't have super clear pointers (at least as far as I can see) as to why they take this long. One thing I did note is that in the first profile (in the top profile / 13.6MB - Firefox 2024-01-12 22.16), the profiler indicates for some loads that it's waiting 60s for a socket thread. I don't know why we'd run out of those / why there would be a problem getting to those threads. Valentin, do you know more about this / do you have suggestions on how to debug further?

(as an aside: do we have telemetry for the time we wait for socket threads that we could use to establish how frequent this is / if there are pathological edgecases / make sure the number of threads etc. is right?)

A bit of a wild guess, but I wonder if, if you run without extensions and revert the preferences:

network.predictor.enabled
network.prefetch-next
network.http.speculative-parallel-limit
network.dns.disablePrefetch

in about:config, if then the problem goes away?

It looks like these preferences can be set by an extension, but I expect that they stay enabled if the extension is disabled (though I could be wrong about this).

In one of the profiles, the webextension storage database is loaded synchronously and this takes a full 10 seconds on startup. Luca, is this normal? (in the top profile / 13.6MB - Firefox 2024-01-12 22.16)

Even if i revert the preferences and run firefox with extensions disabled the issue persists

Comment 18

[klebbutdifferent]

Sorry about that. I meant to say that even when i disable extensions and revert the preferences the issue persists.

Comment 19

[Valentin Gosu [:valentin]]

Attachment: Extension suspend.png

Looking at Firefox 2024-01-13 09.52 profile.json.gz
it looks like the channels for the page load are hanging because they're being suspended by ublock origin, and are never resumed.

Could you also capture a profile with all extensions disabled?

Comment 20

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

(In reply to Luca Greco [:rpl] [:luca] [:lgreco] from comment #16)

Hi Gijs,
based on a quick look to the first and last profile I'm assuming that for webextension storage database you mean the webext_storage_bridge which is part of the storage.sync rust based backend.

Hi Mark, would you mind to take a look at the profile to provide your perspective about what may be going on and how we may followup to investigate further and/or plan to fix this issue?

I took another quick look to the stack of calls related to the rust-based storage.sync visible in the flame graph and it looks to be due to sqlite WAL recovery (triggered as soon as we open the database, apparently as a side-effect of checking if the database is empty when it gets lazily opened for the first time), as the profile shows that is currently being executed on the main thread (and based on a quick look that may be one of the few operations on the database that are being executed on the main thread, based on a quick look the other operations are being executed in a separate background thread).

Let's hear Mark's perspective about what is visible in the attached profile, he has much more direct experience and knowledge than myself about this part of the storage.sync internals.

Comment 21

[klebbutdifferent]

(In reply to Valentin Gosu [:valentin] (he/him) from comment #19)

Created attachment 9376940 [details]
Extension suspend.png

Looking at Firefox 2024-01-13 09.52 profile.json.gz
it looks like the channels for the page load are hanging because they're being suspended by ublock origin, and are never resumed.

Could you also capture a profile with all extensions disabled?

I will as soon as possible

Comment 22

[klebbutdifferent]

(In reply to Valentin Gosu [:valentin] (he/him) from comment #19)

Created attachment 9376940 [details]
Extension suspend.png

Looking at Firefox 2024-01-13 09.52 profile.json.gz
it looks like the channels for the page load are hanging because they're being suspended by ublock origin, and are never resumed.

Could you also capture a profile with all extensions disabled?

here it is
https://share.firefox.dev/3vVO1fL

Comment 23

[Valentin Gosu [:valentin]]

Thank you for the profile.
I'm not sure this is a networking issue. I see 2 large main thread janks coinciding with the channels hanging.
The first one is 14s and goes through webext_storage_bridge::store::init_store
Second one is 5 seconds and goes through mozilla::layers::PCompositorBridgeChild::SendFlushRendering

It could be that they are both IPC related?

Comment 24

[Tarik Eshaq [:teshaq]]

init_store ends up opening a SQLite database, which is I/O that shouldn't be on the main thread. We've taken steps to make sure webext storage I/O does not happen on the main thread but it seems like this callstack does.

At the very least making sure that call doesn't happen on the main thread seems actionable

Comment 25

[Mark Hammond [:markh] [:mhammond]]

I believe we fixed this at the time, but I'm not bothering to find where because since then we replaced the offending code entirely with uniffi generated code which wouldn't allow this to happen in the first place.