Open Bug 1630225 Opened 5 years ago Updated 5 months ago

3+ minute long session restores on AMD E2-7110, Linux

Categories

(Firefox :: Session Restore, defect)

Product:
Firefox
Component:
Session Restore
Version:
75 Branch
Platform:
Unspecified
Linux
Type:
defect

Tracking

()

People

(Reporter: yoasif, Unassigned)

References

Details

Initially reported at: https://www.reddit.com/r/firefox/comments/g0myck/4_minutes_startup_time/

Basic information

Steps to Reproduce:

Restore from session

Expected Results:

Fast restore.

Actual Results:

3+ minute long session restores.

More information

Profile URL: https://perfht.ml/2ydmFUs

Basic systems configuration:

OS version: linux mint 19.3

GPU model: Advanced Micro Devices, Inc. [AMD/ATI] Mullins [Radeon R3 Graphics]

Number of cores: 4 (AMD E2-7110)

Amount of memory (RAM): 8GB

Thanks so much for your help.

I re-symbolicated the profile: https://perfht.ml/3afaKTl (with help from bug 1630340 and a fix for #2497).

I can see a few things in it:

  1. Unfortunately, the first ~2 minutes (106.7 seconds) of parent process activity were lost because the buffer was too small.
  2. During the next 3 minutes, I'm pretty sure Firefox thinks its window is open - it draws an animation, probably the tab loading throbber.
  3. At the 4min20s mark, AppWindow::WindowActivated() is called. I think this just means that the window was focused, not that it was shown. So it presumably was shown before then.

Due to the missing data I'm going to ask for a new profile in the reddit thread.

Some other things I noticed:

  1. There's a DOM Worker thread that polls a sub process for at least a minute or so. Not sure what sub process that could be.
  2. Mouse move events seem very inefficient because Event::GetScreenCoords involves a slow round-trip to the X server.

I'm tempted to suspect that some addons are blocking network requests until they are done initializing themselves (and waiting for data, eg. from IndexedDB). Bug 1625006 landed markers to show when network requests are blocked by webextensions, so if the same profile was captured on a recent nightly we could be sure.

But I'm not really convinced by this explanation for this profile because there's something else that's odd: network requests seem to start normally in the content process #1, to be very significantly delayed in content process #4, and to start later in content process #3.

This is likely related to session store and/or add-ons. Removing it from the perf component, as this particular issue and its underlying cause are probably not representative of an issue that's widely experienced.

Component: Performance → Storage: localStorage & sessionStorage

(In reply to Markus Stange [:mstange] from comment #1)

Due to the missing data I'm going to ask for a new profile in the reddit thread.

The user did not report back on reddit after Markus' post, it seems? In the current state, I see nothing actionable here for Storage. I'll wait for some other day, though.

Flags: needinfo?(jstutte)

Bas, I assume you meant to transfer this to Session Restore instead of sessionStorage? Please revert this change if I misunderstood it.

Component: Storage: localStorage & sessionStorage → Session Restore
Product: Core → Firefox

This was the last one. Shorter, but still several seconds of idle CPU.

https://share.firefox.dev/3cNO65O

(In reply to Markus Stange [:mstange] from comment #1)

  1. There's a DOM Worker thread that polls a sub process for at least a minute or so. Not sure what sub process that could be.

This shows up in the two new profiles as well. I think this is the cause.
This worker thread gets started around the time when the main thread runs Subprocess.jsm code from NativeMessaging.jsm.

So I think this delay is somehow caused by the native messaging integration of an add-on, which takes too long to finish running its native command. Atillio, could find out if one of your add-ons is responsible?

Florian, I think it would be a good idea to make subprocess_worker_unix.js create a profiler marker with the subprocess command.

These were my addons in all my previous tests:

  1. FF multi-account containers
  2. Adblock plus
  3. Video DownloadHelper
    nothing else.

And this is the new output after disabling Video downloadhelper: shorter startup time, still a few seconds of lag.
https://share.firefox.dev/2MNuCDK

I wonder if it has something to do with the remaining two addons, or firefox sync.. or maybe some hardware detection.. (no idea)

Another question.. is it enough to DISABLE an addon? or should I REMOVE it?

The profiles in comment 6, 7 and 9 all have 2 long onBeforeRequest markers caused by "@testpilot-containers, uBlock0@raymondhill.net". Given that we have much shorter onBeforeRequest markers for all following requests, I'm tempted to suspect it's @testpilot-containers that's related to the problem.

(In reply to Attilio from comment #9)

I wonder if it has something to do with the remaining two addons, or firefox sync.. or maybe some hardware detection.. (no idea)

I suspect the "FF multi-account containers" add-on, so you might try with that add-on disabled to see if it helps. And yes, disabling the add-on should be enough.

Another thing I've noticed: in the profile from comment 6, the parent process main thread gets blocked for more than 5s trying to launch the Remote Data Decoder process.

(In reply to Markus Stange [:mstange] from comment #8)

(In reply to Markus Stange [:mstange] from comment #1)

  1. There's a DOM Worker thread that polls a sub process for at least a minute or so. Not sure what sub process that could be.

This shows up in the two new profiles as well. I think this is the cause.

I don't think this is the cause because the network loads get unblocked before the activity in this subprocess worker finishes. Also, the profile in comment 9 without "Video downloadhelper" no longer has the subprocess activity, but still has the issue.

Florian, I think it would be a good idea to make subprocess_worker_unix.js create a profiler marker with the subprocess command.

Even if it's not the cause, it would still be interesting to better understand what happens there. We could add a marker around https://searchfox.org/mozilla-central/rev/0e09b9191c02097034e46b193930f91c45b7885d/toolkit/modules/subprocess/subprocess_worker_unix.js#384 with the command and arguments. Or for something more generic, we could add the marker around https://searchfox.org/mozilla-central/rev/0e09b9191c02097034e46b193930f91c45b7885d/toolkit/modules/subprocess/Subprocess.jsm#160

I have not tried adding the marker as I couldn't find an easy way to reproduce.

Looking for manifest files in these locations https://developer.mozilla.org/en-US/docs/Mozilla/Add-ons/WebExtensions/Native_manifests#Linux should help to guess which command might have been executed through NativeMessaging.

Here two new tests:

FF multi-account containers + Adblock plus: https://share.firefox.dev/3dZlWpL

And this is with ublock origin ONLY (ff multi-account container disabled, not uninstalled) -> 15-20 seconds of idle cpu before it starts loading web pages. https://share.firefox.dev/3fdWL2W

Flags: needinfo?(jstutte)
You need to log in before you can comment on or make changes to this bug.