696141 - [meta] Add-ons Manager has Ts costs

Status: RESOLVED INCOMPLETE

(Firefox for Android Graveyard :: General, defect, P3)

Description

[Kevin Brosnan [Ex-Mozilla]]

http://graphs-new.mozilla.org/graph.html#tests=[[16,27,20],[16,52,20],[16,63,20]]&sel=none&displayrange=14&datatype=running

The best Ts numbers before October 18th were ~1600ms after the best are ~1950

Suspect enabling the extension manager.

Comment 1

[[:fabrice] Fabrice Desré]

On first startup the extension manager creates a sqlite db. That may very well cause this regression

Comment 2

[Brad Lassey [:blassey] (use needinfo?)]

(In reply to Fabrice Desré [:fabrice] from comment #1)
> On first startup the extension manager creates a sqlite db. That may very
> well cause this regression

can we confirm that?

Comment 3

[[:fabrice] Fabrice Desré]

I added some timing to the add-on startup, here's a typical run on a G2:

W/PluginManager(29568): zerdatime 1319225175239 - runGecko
E/nsConsoleService(29568): Could not read chrome manifest file '/data/data/org.mozilla.fennec_fabrice/chrome.manifest'.
E/nsConsoleService(29568): LOG addons.manager: Application has been upgraded
E/nsConsoleService(29568): LOG addons.xpi: startup
E/nsConsoleService(29568): LOG addons.xpi: checkForChanges
E/nsConsoleService(29568): LOG addons.xpi: Opening database
E/nsConsoleService(29568): LOG addons.xpi: Opening database took 8 ms
E/nsConsoleService(29568): LOG addons.xpi: Migrating data from extensions.rdf
E/nsConsoleService(29568): LOG addons.xpi: Migrating data took 1 ms
E/nsConsoleService(29568): LOG addons.xpi: Creating database schema
E/nsConsoleService(29568): LOG addons.xpi: Creating database took 145 ms
E/nsConsoleService(29568): LOG addons.xpi: No changes found
E/nsConsoleService(29568): LOG addons.xpi: Add-ons list is missing, recreating
E/nsConsoleService(29568): LOG addons.xpi: Writing add-ons list
E/nsConsoleService(29568): LOG addons.xpi: Writing add-ons list took 29 ms
E/nsConsoleService(29568): LOG addons.xpi: checkForChanges took 398 ms
E/nsConsoleService(29568): LOG addons.xpi: startup took 413 ms
E/nsConsoleService(29568): fs_handle
E/nsConsoleService(29568): fs_handle: about:support
E/nsConsoleService(29568): fs_handle: [xpconnect wrapped nsIURI]
E/nsConsoleService(29568): fs_handle: done

So startup cost is about 400ms on first run, and around 50ms on the following runs.

Comment 4

[Doug Turner (:dougt)]

This database is the largest file in my profile:

-rw------- app_109  app_109    393216 2011-10-22 08:34 extensions.sqlite
-rw------- app_109  app_109       512 2011-10-22 08:34 extensions.sqlite-journal

Comment 5

[Dave Townsend [:mossop]]

Taking care of needlessly creating the database in bug 697246

Comment 6

[Dave Townsend [:mossop]]

It's probably worth listing the different types of startup that will have different amounts of Ts impact for the add-ons manager:

1. First run, no extensions installed
2. First run, some extensions installed
3. App updated, no extensions installed
4. App updated, some extensions installed
5. Normal startup, no extensions installed
6. Normal startup, some extensions installed
7. Startup following the installation/uninstallation of an extension

Of these all except 5 and 6 will open the database. Bug 697246 stops us touching the database for 1 giving a decent saving for the first run.

Bug 697314 has impact on 1 and 2 and unless we fix pref saving all the rest too.

Bug 697312 mainly affects 1 and 3.

Bug 697331 has a small impact on all.

If we get patches landed for all those then 1 and 3 will be about the same as 5 (around 30ms currently). I don't think we have measurements of the other cases yet.

Comment 7

[Justin Dolske [:Dolske]]

Just to record this somewhere (is there a better bug?), the thread that spawned this bug also noted some concern with a 2.5MB increase in RSS from using add-ons mgr. Most of that looks to be sqlite overhead (shocker!) -- even with basically empty DBs, I see lots of memory (~.5 MB in about:memory) being used for DB that are essentially empty. addons.sqlite and extensions.sqlite my desktop profile, as well as permissions.sqlite (see also bug 697314).

Comment 8

[Doug Turner (:dougt)]

I see lots of work deferring the problem until an addon has been installed.  My worry is that many of the fennec users have addons installed, so they will all see this big memory and time hit.

any progress here?

Comment 9

[Justin Dolske [:Dolske]]

I'd bounce this to Dave, but Blair is the new module owner, so... :)

AFAIK, this bug is basically fixed, by Dave either deferring work or speeding up the work it does do.

Do we have fennec data that indicates this is still a problem (with or without an installed addon), and what those costs are?

Comment 10

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(In reply to Justin Dolske [:Dolske] from comment #9)
> Do we have fennec data that indicates this is still a problem (with or
> without an installed addon), and what those costs are?

Indeed: need more (recent) data.

Comment 11

[Doug Turner (:dougt)]

Blair, that data you need, you are collecting, right? 


Is there anything you need?

Comment 12

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(In reply to Doug Turner (:dougt) from comment #11)
> Blair, that data you need, you are collecting, right? 

Not unless you don't mind waiting a few months (I'm rather backed up).

> Is there anything you need?

Replication of comment 3, for the scenarios listed in comment 6, using the latest on mozilla-central.

Comment 13

[Doug Turner (:dougt)]

The problem continues.  And the core problem needs to be fixed.

Try this:

1) install beta.
2) load about:memory
3) look at a values for storage
4) go to https://addons.mozilla.org/en-US/android/
5) install *any* add-on
6) restart if required
7) load about:memory

What you will see is that after installing the first add-on, you get a large memory hit:

.53MB extensions.sqlite
.48MB addons.sqlite

some large percentage of the "other" 1.22MB

Taking a 1MB+ hit for a single add-on seems really bad.  The good news is that it looks like it is a one time charge - that is, we don't use 1MB per add-on -- just 1mb for all add ons.

Comment 14

[Gian-Carlo Pascutto [:gcp]]

The RSS issue from the plugin sqlite database looks like it could be solved by reducing the pages size or the amount of pages cached for SQLite. It makes no sense to have 0.5M databases and caches that likely contain maybe 10k of data.

Given that *Gecko* SQLite is irrelevant in Fennec, I think this might be as simple as turning those settings down?
 
The main users that are still left would be the SQLiteBridge users. Migration is one time and not actually limited on the Gecko DB side, and then there's password manager, which I presume isn't performance limited at all.

Comment 15

[Wesley Johnston (:wesj)]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #14)
> Given that *Gecko* SQLite is irrelevant in Fennec, I think this might be as
> simple as turning those settings down?

Just to clarify, we still have more than a few consumers of Gecko's sqlite (passwords, form history, addons manager, indexed-db, and any addons that create their own storage databases like adblock, stylish, or greasemonkey). We really only knocked out one db that I know of, places (although it was a big one).

Comment 16

[Gian-Carlo Pascutto [:gcp]]

I suspect those aren't as performance sensitive, so it may still be fine. Also, we have no idea if the current value is optimal on Android.

That said, once a database is created you can't really change the page size, so for old profiles this is a pain. We might be able to tune the cache sizes, though. And we can do that per-database.

Comment 17

[Justin Dolske [:Dolske]]

Oops, forgot to follow up here. Talked with Blair earlier in the week, and have a plan to gather some data to help figure out what's going on and exactly what to fix.

Comment 18

[Doug Turner (:dougt)]

dolske, does the plan include what gcp suggested in comment #14?

Comment 19

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Yes. I looked at the SQLite docs and got a bit confused, but I believe it's doable per-database. Filed bug 726556 to look into that separately.

Comment 20

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Attachment: Timing patch v1

For future reference, this patch adds a bunch of additional logging that includes timing for startup related functions, as well as other API calls.

Comment 21

[Marco Bonardo [:mak]]

to add to the slow startup path, XPIProvider.jsm still uses synchronous Storage, so if it's used on startup could be expensive (Bug 699839).

Comment 22

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Attachment: Timing patch v1.01

I need to stop bitrotting myself...

Comment 23

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Attachment: Timing patch v1.1

Found some unexpected results, where startup of XPIProvider was small compared to overall AddonManager startup. This adds logging to time other providers too.

Comment 24

[:Margaret Leibovic]

Attachment: logging in various scenarios

I tried to test the different types of startup Mossop mentioned in comment 6, but I wasn't sure how to test app updates, or how to have an add-on installed before first run.

Comment 25

[Blair McBride [:Unfocused] (UNAVAILABLE)]

That shows that loading the code for the providers is taking ages. Far longer than actually starting them up. Which is interesting. But I guess XPIProvider is ~8k LoC. Wonder how much of that code we could easily lazy-load (such as XPIDatabase).

checkForChanges also takes ages, but that was expected - it's a bunch of unavoidable IO. Thankfully it would be relatively rare to hit that during real-world usage (few people install/uninstall an extension *every time* they use the browser).

Comment 26

[Johnathan Nightingale [:johnath]]

Touched this in triage - it remains a final blocker for Fennec, but there's some confusion about our current state (is there still a Ts hit? Is there a memory hit?)

Comment 27

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(In reply to Johnathan Nightingale [:johnath] from comment #26)
> Touched this in triage - it remains a final blocker for Fennec, but there's
> some confusion about our current state (is there still a Ts hit? Is there a
> memory hit?

I have some worked planned here, but I'm blocked on not having enough hours in the day. Gonna push everything else aside later today, and work on this.

Some Ts hit in unavoidable, it's just a matter of if anything can be done to reduce it. We have measurements that say just loading of code is the biggest part of the Addons Manager startup time (for typical startups). So I'm going to try do some refactoring to lazy-load as much code as possible.

Same deal with memory. See bug 726556 for reducing database memory usage, which is the main issue, and fixable in the short-term. I have some other things planned (AddonRepoistory isn't smart about caching), but that requires a partial rewrite of older code, so is longer term work.

Comment 28

[Mark Finkle (:mfinkle) (use needinfo?)]

Blair - Any update on this? I thought I remembered you mentioned an improvement with some patches in IRC,

Comment 29

[Justin Dolske [:Dolske]]

Oof, yeah this is overdue for an update although plenty of work's been going on. Sorry for not communicating more. Blair's been doing some debugging, has a number of devices to test with, and the last update IIRC was that there's a ~30% win by refactoring things so that much less code is pulled in on startup (even when an addon in installed).

Comment 30

[(dormant account)]

There is potential for improvement if bug 729330 is addressed.

Comment 31

[Johnathan Nightingale [:johnath]]

This has taken too long, but we can't hold the release on it. I'd really like to see this land soon, though, so that it rides a future Fennec train early out the gate.

Comment 32

[Justin Dolske [:Dolske]]

Blair, can you attach and/or mark dependent bugs that contain the stuff you'd found so far?

Comment 33

[Mark Finkle (:mfinkle) (use needinfo?)]

Treating like meta. Looks like dependent bugs have been fixed. If this is finished, please close.

Comment 34

[Sylvestre Ledru [:Sylvestre]]

Moving to p3 because no activity for at least 24 weeks.

Comment 35

[BMO Automation]

We have completed our launch of our new Firefox on Android. The development of the new versions use GitHub for issue tracking. If the bug report still reproduces in a current version of [Firefox on Android nightly](https://play.google.com/store/apps/details?id=org.mozilla.fenix) an issue can be reported at the [Fenix GitHub project](https://github.com/mozilla-mobile/fenix/). If you want to discuss your report please use [Mozilla's chat](https://wiki.mozilla.org/Matrix#Connect_to_Matrix) server https://chat.mozilla.org and join the [#fenix](https://chat.mozilla.org/#/room/#fenix:mozilla.org) channel.