789193 - AMI_startup() takes 200ms on mobile, 26ms on desktop at startup

Status: RESOLVED INCOMPLETE

(Toolkit :: Add-ons Manager, defect, P3)

Description

[Benoit Girard (:BenWa)]

Found using eideticker profiling.

Profile:
http://people.mozilla.com/~bgirard/cleopatra/?zippedProfile=profiles/sps-profile-1346944481.42.zip&videoCapture=videos/video-1346944481.42.webm

Function:
http://mxr.mozilla.org/mozilla-central/source/toolkit/components/passwordmgr/storage-mozStorage.js#191

Comment 1

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

I assume the function you meant to link to is:
http://mxr.mozilla.org/mozilla-central/source/toolkit/mozapps/extensions/AddonManager.jsm#443

Comment 2

[Benoit Girard (:BenWa)]

Opps, yes

Comment 3

[Dave Townsend [:mossop]]

Is this startup with a new profile or an existing profile? It makes quite a difference

Comment 4

[Benoit Girard (:BenWa)]

New profile. It shows up on every run of eideticker.

Comment 5

[David Teller [:Yoric] - still alive but not very active]

I will try and give a hand, if I can reproduce the measurements.
Since I have never used eideticker, I hope you will bear with my newbishness.

Is this something that I can reproduce with eideticker with Telemetry? If so, could I instrument the code to determine exactly what part of the function takes so much time?

Comment 6

[Benoit Girard (:BenWa)]

You should be able to reproduce by creating a new profile and adding code to measure how much time we spend in AMI_startup(), no need to use eideticker.

Comment 7

[David Teller [:Yoric] - still alive but not very active]

So far, examining the eideticker profile does not seem to reveal any bottleneck inside |AMI_startup()|. The only cost that seems non-trivial is a single call to the JS tokenizer that lasts 10ms.

I will keep investigating.

Comment 8

[Benoit Girard (:BenWa)]

Actually I see this on a warn restart of my existing profile on desktop except that takes up 26ms. Not cheap for desktop.

Comment 9

[(no longer active)]

According to this startup profile, we spend 100ms on existing profiles for this on mobile: http://people.mozilla.com/~bgirard/cleopatra/?report=439a965571b0283876e8d75722d7a370b5b49c52

Can we do something about this?

Comment 10

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(In reply to Benoit Girard (:BenWa) from comment #4)
> New profile.

On a new profile, I've seen XPI_importPermissions() take up a large chunk of time - which is bug 697314.

(In reply to :Ehsan Akhgari from comment #9)
> According to this startup profile, we spend 100ms on existing profiles for
> this on mobile:

I did some measurements on mobile some time ago (see bug 696141), and *by far* the greatest amount of time for normal startups was spent simply loading code (*not* executing any functions). Bug 746909 and bug 746916 moved a decent size chunk of code to be lazy-loaded - but there's a lot more code that can be lazy loaded. Filed bug 846240 to track all that.

Comment 11

[Jean Claveau]

This issue just happened on my Xubuntu laptop but the profile is really longer than 26ms :/

http://people.mozilla.com/~bgirard/cleopatra/#report=77b69f26c0ae748cbca9fcb1da73e248e3d9ae5c

Hoping it can help.

Comment 12

[David Teller [:Yoric] - still alive but not very active]

Irving, do you know if that's still valid?

Comment 13

[:Irving Reid (No longer working on Firefox)]

Blair - when you did your startup measurements that pointed at code loading time, were you running debug or opt builds? One thing I've noticed is that loading code takes much longer (up to 10x) on debug builds.

From Ehsan's profile in comment 9, it does look like we're spending almost 100ms in AMI_startup; if I'm reading the profile correctly, quite a bit of that is loading and parsing JS. It would be nice to see some new profiles of Android startup; if we still see significant code loading delays then the lazy loading changes in bug 846240 are the next step.

Note that AMI_startup includes both the addon manager's internal setup, loading all the extension providers, and loading and running the bootstrap routines for restartless add-ons; if your profile has any add-ons that will affect the results.

You can see timing information for this in the about:telemetry Simple Measurements section; for example, on my most recent Nightly (these are time since browser startup in milliseconds):

AMI_startup_begin 	132
XPI_startup_begin 	140
XPI_bootstrap_addons_begin 	218
XPI_bootstrap_addons_end 	383
XPI_startup_end 	383
AMI_startup_end 	383 

so it took less than 8ms to load the XPI provider code (between AMI_startup_begin and XPI_startup begin), 78 ms. to load the XPI database and process the changes from my Nightly upgrade (this doesn't happen on normal restarts), and 165ms to run bootstrap addon startup methods.

Even with the JSON AddonDatabase (bug 853389) and XPIDatabase (bug 853388), startups on a completely new profile will be slightly slower than on a warm profile because we scan for existing add-ons, initialize some files and preferences, and may need to lazy-load XPIDatabaseUtils.js to create the initial JSON database.

Comment 14

[:Irving Reid (No longer working on Firefox)]

(In reply to Jean Claveau from comment #11)
> This issue just happened on my Xubuntu laptop but the profile is really
> longer than 26ms :/
> 
> http://people.mozilla.com/~bgirard/cleopatra/
> #report=77b69f26c0ae748cbca9fcb1da73e248e3d9ae5c
> 
> Hoping it can help.

Thanks for the profile; in your case it's showing the startup time is spent in XPI_showUpgradeUI(), which should only happen on the first run with a new version of Firefox; the time is spent checking to ensure that all your add-ons are compatible with the new version. We're working on improving that in bug 760356.

Comment 15

[Nathan Froyd [:froydnj]]

(In reply to :Irving Reid from comment #13)
> From Ehsan's profile in comment 9, it does look like we're spending almost
> 100ms in AMI_startup; if I'm reading the profile correctly, quite a bit of
> that is loading and parsing JS. It would be nice to see some new profiles of
> Android startup; if we still see significant code loading delays then the
> lazy loading changes in bug 846240 are the next step.

I can confirm that this still happens in recent builds on the first run of every profile (the profile is addon-less).  Less recent-ish builds (maybe from a month or so ago?) definitely showed this slowdown on old profiles too.

Comment 16

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

filter on [mass-p5]

Comment 17

[James Willcox (:snorp) ([e-mail]) (he/him)]

I still see this, though it looks closer to 400ms

Comment 18

[(inactive) Jim Chen [:jchen] [:darchons]]

I don't think this should track beta, because it really consists of many small parts that will take a while to sort out. Here are the 15 top times spent in AMI_startup (640ms) on a Nexus 4. Worst offender seems to be when we import JS modules 77 times, which take up a large chunk of time.

236.716  import <native> (77x)
36.289   getService <native> (13x)
32.352   ctypes.jsm:1
23.440   osfile_shared_allthreads.jsm:1
19.441   XPIProvider.jsm:1
13.032   osfile_async_front.jsm:1
11.659   osfile_unix_allthreads.jsm:1
9.644    nsBlocklistService.js:1	
9.583    addObserver <native> (23x)
9.309    Barrier/this.client.addBlocker (AsyncShutdown.jsm:630) (6x)
8.515    AMI_startup (AddonManager.jsm:739)
8.118    TelemetrySession.jsm:1
5.768    next (self-hosted:462) (35x)
5.646    XPI_checkForChanges (XPIProvider.jsm:3688)
5.280    PromiseSet.prototype.add (AsyncShutdown.jsm:136) (6x)

Comment 19

[Sylvestre Ledru [:Sylvestre]]

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

Comment 20

[William Lachance (:wlach)]

I don't think it's useful to keep this open.