Closed Bug 789193 Opened 12 years ago Closed 6 years ago

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

Categories

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

ARM
Android
defect

Tracking

()

RESOLVED INCOMPLETE
Tracking Status
fennec + ---

People

(Reporter: BenWa, Assigned: jchen)

References

Details

(Keywords: perf, platform, Whiteboard: [sps][snappy:p1])

Opps, yes
Keywords: perf
OS: Mac OS X → Android
Product: Fennec → Firefox for Android
Hardware: x86 → ARM
Component: General → Add-ons Manager
Product: Firefox for Android → Toolkit
Is this startup with a new profile or an existing profile? It makes quite a difference
New profile. It shows up on every run of eideticker.
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?
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.
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.
Actually I see this on a warn restart of my existing profile on desktop except that takes up 26ms. Not cheap for desktop.
Summary: AMI_startup() takes 200ms on startup → AMI_startup() takes 200ms on mobile, 26ms on desktop at startup
Whiteboard: [sps] → [sps][snappy]
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?
Blocks: 807322
tracking-fennec: --- → ?
tracking-fennec: ? → +
Whiteboard: [sps][snappy] → [sps][snappy:p1]
(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.
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.
Depends on: 895032
Irving, do you know if that's still valid?
Flags: needinfo?(irving)
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.
Flags: needinfo?(irving)
(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.
(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.
filter on [mass-p5]
Priority: -- → P5
I still see this, though it looks closer to 400ms
tracking-fennec: + → ?
Assignee: nobody → snorp
tracking-fennec: ? → 40+
Assignee: snorp → nchen
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)
tracking-fennec: 40+ → ---
tracking-fennec: --- → ?
tracking-fennec: ? → +
Priority: P5 → P1
Moving to p3 because no activity for at least 24 weeks.
Priority: P1 → P3
I don't think it's useful to keep this open.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.