Having a larger number of tabs slows down cold startup

[agi90]

While doing an unrelated startup performance investigation, I noticed that having a large number of tabs significantly slows down cold startup (tested on latest Fenix nightly).

This is the test I was running:

PACKAGE=org.mozilla.fenix.nightly
PAGE=https://www.google.com

echo "Warming up..."
adb shell pm clear $PACKAGE
adb shell am start -a android.intent.action.VIEW -d $PAGE
sleep 120

adb shell am force-stop $PACKAGE
adb shell am kill-all
adb logcat -c

echo "testing..."
while true; do
  adb shell am start -a android.intent.action.VIEW -d $PAGE
  sleep 15
  adb shell "input keyevent HOME"
  sleep 1
  adb shell am force-stop $PACKAGE
done

An empirical result is below, x axis is number of tabs, y axis is startup time to fragment rendered in milliseconds, purple points are raw measurements and green points are average [0, x] with error bars.

┆Issue is synchronized with this Jira Task

[agi90]

After looking into it more, this seems to be (partially) caused by registerWebExtension. I modified the test to not open a new tab every time (pressing BACK instead of HOME in the above test). And the increase in startup time is still noticeable (although less pronounced) on nightly, but not on the branch that uses installBuiltIn. See below graph (green = nightly, purple = installBuiltIn)

[agi90]

Possibly relevant for the above https://bugzilla.mozilla.org/show_bug.cgi?id=1639978

[agi90]

More graphs! I ran the installBuiltIn test overnight to make sure the non-increase wasn't an accident and it doesn't seem to be, after 1000 restarts the startup time is still consistent.

[agi90]

After further testing the registerWebExtension vs installBuiltIn problem seems to be a red herring (had a bad local build). So the only difference here is the number of tabs.

[canova]

Probably late to the party, but I think a startup profile could give some useful insight on the problem :) There is a documentation on how to profile the fenix startup here: https://profiler.firefox.com/docs/#/./guide-remote-profiling?id=startup-profiling-fenix

[mcomella]

See mozilla-mobile/fenix#7035 for an older version of this issue.

[mcomella]

Triage: we may revisit as part of the holistic startup effort; but otherwise let's revisit this next week.

[agi]

One thing I've seen implied somewhere else is that we think that such a slow down is inherently necessary? I feel like we should be able to make startup time not depend on number of tabs at all (within a few orders of magnitude). Besides the first few tabs all we need to read at startup is the URL/Title, we can load screenshots / all the metadata lazily if the user scrolls the tab view, or just a little later after startup.

[jonalmeida]

@csadilek made a note that he wasn't able to see this issue any more and indeed after loading 150 tabs as well (I used your script to keep it as close to your initial testing), I'm not seeing any slow down.

We've had many perf fixes go in already in various levels that we might have fixed this inadvertently!

@agi are you able to reproduce the slow down any more on the latest nightly?

[agi]

I'll run some tests overnight!

[agi]

The bug is still there, the purprle line is the average with errorbars and green line are raw measurements for x number of tabs. You can see that the average trends up, it seems to be less pronounced now? But it's still half a second with 200 tabs.

[mcomella]

@agi What phone are these analyses taken from?

[agi]

@mcomella Samsung S7

[jonalmeida]

I took a few measurements myself with the two test devices I had. I also have a Nexus 5 but simpleperf doesn't seem to work on Android 6.0

Start-up Profile (15-09-20, e6ee13dcb)

Attempt	Link	Notes	Device
1	https://share.firefox.dev/35GuKzK	Clean install	Pixel 4
2	https://share.firefox.dev/33w23Tf	Clean install	Pixel 4
3	https://share.firefox.dev/2E4NZrh	150 tabs restored	Pixel 4
4	https://share.firefox.dev/3hDnff4	150 tabs restored	Pixel 4
5	https://share.firefox.dev/2ZIwIvo	150 tabs restored	Pixel 4
6	https://share.firefox.dev/35GB9dV	1 tab restored	Pixel 4
7	https://share.firefox.dev/32EDLar	Clean install	Pixel 2
8	https://share.firefox.dev/3iTrJ2R	1 tab restored	Pixel 2
9	https://share.firefox.dev/3mG0ISK	1 tab restored	Pixel 2
10	https://share.firefox.dev/32DgOEr	150 tabs restored	Pixel 2
11	https://share.firefox.dev/3kqiMOx	150 tabs restored	Pixel 2

When performing a clean install, I didn't notice anything significant happening there either.

The results are not consistent from some issues I've had with measuring startup, but there are some noticeable increases in launch time when loading 150 tabs from SessionManager.restore which is roughly 300ms more. This would make sense since we're reading in more session from disk during restore.

I'm not sure just yet what we can do about this. A naive solution would be to remove the syncDispatch calls and make it async, but that will probably lead to really weird states. I need to investigate if this is only an issue because of the synchronized states of SessionManager to BrowserState that we have during the migration to deprecation SessionManager.

[mcomella]

Thanks for looking into this, jonalmeida.

+300ms seems like a very long time for 150 items, especially for a P2/P4: what are we restoring? Is there some part of the session we should be loading on-demand (e.g. thumbnails or similar)? Are we blocking for gecko to finish loading to give us the session? We should identify the root cause of this seemingly abnormal duration in order to determine an appropriate fix.

fwiw, the ideal state for startup is that we aren't blocking the main thread for IO at all. In some cases the complexity is not worth it (e.g. Gecko initialization) but the FE perf team isn't at a point where we can identify where all the main thread-blocking IO is occurring and which ones are worth keeping due to the complexity. Try to keep this in mind as you design a solution: we're not asking for a non-blocking solution today but we might ask for it tomorrow. :) Chrome basically does nothing on startup so we need to do everything we can to compete.

[mcomella]

We believe #8535 may (partially? fully?) address this issue.

[jonalmeida]

An update for the issue: we've landed our fixes in AC, however due to some build pipeline issues, we haven't got this into Fenix yet.

[jonalmeida]

We have a new nightly with the latest AC version in it (verified from About Fenix with the git SHA ab29a90c8) that has our performance fix.

@agi you should see some changes to the cold start-up time now. 🙂

[agi]

New graphs/numbers coming soon :)

[agi]

Looks so much better now! There still seems to be a little inflection of about ~100ms (but it could definitely be noise). As far as I'm concerned this is fixed. Good job everyone!

[jonalmeida]

Thanks @agi and @csadilek !

[mcomella]

Curious, compared to the graph from Sept 1 #7304 (comment), the absolute values are faster too – from 4500ms on Sept 1 to ~3750ms today. 🤔

[agi]

@mcomella I wouldn't pay too much attention to the absolute numbers, there's a lot of factors that can impact perf on this device, it's definitely non in a clean state every time.

I can, however, do a test before/after back-to-back which should be way more accurate, if you're interested.