634792 - browser-ui.js:UIReadyDelayed startup optimization opportunities

Status: RESOLVED WONTFIX

(Firefox for Android Graveyard :: General, defect)

Description

[Alon Zakai (:azakai)]

Profiling shows that browser-ui.js's event listener for UIReadyDelayed takes a sizable amount of time on startup. Specifically,

  Cc["@mozilla.org/satchel/form-history;1"].getService(Ci.nsIFormHistory2);

takes 0.44 seconds on first run, and

  WeaveGlue.init();

takes 0.1 seconds on first run as well as later runs.

Measurements were taken on a Galaxy S, Android 2.1.

Comment 1

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

That's kinda the reason UIReadyDelayed exists - to run expensive startup stuff after the app is finished the actual startup process.

If we can make some of the expensive stuff less costly, great!

Comment 2

[Alon Zakai (:azakai)]

On an HTC desire I see UIReadyDelayed now taking 0.73 seconds on first load, and 0.35-0.45 seconds on warm startup. That's enough to lag the UI. Perhaps we should split it up into smaller bits (if possible)?

Comment 3

[Alon Zakai (:azakai)]

Attachment: split up UIReadyDelayed actions

This patch splits up the actions in UIReadyDelayed and introduces some delay in between them. With this, I get a maximum delay of 200ms during first load (compared to 700ms without this patch), and 75ms during later loads (compared to 400ms without this patch). So I think this can prevent some UI lag that might otherwise be noticeable in some cases.

Comment 4

[Alon Zakai (:azakai)]

Attachment: patch with -w

Here is a patch with -w for readability.

Comment 5

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

This is a neat patch. I am trying to dream up a more elegant way of creating the "actions" and will review soon.

Comment 6

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

Comment on attachment 558653 [details] [diff] [review]
split up UIReadyDelayed actions

Some thoughts:
* Can we group more of the like-things together without affecting performance? Like all the xxx.getService() calls in one function, all the XxxView.init() calls in one function and all the xxx.init() calls in one function

* Can we just stop "pre-loading the content process? Do we even know if this helps?

* How can we open this mechaism up to add-ons? We could make the array of action use a "DelayedActions.register(aAction)" style helper object.

Comment 7

[Alon Zakai (:azakai)]

(In reply to Mark Finkle (:mfinkle) from comment #6)
> Comment on attachment 558653 [details] [diff] [review]
> split up UIReadyDelayed actions
> 
> Some thoughts:
> * Can we group more of the like-things together without affecting
> performance? Like all the xxx.getService() calls in one function, all the
> XxxView.init() calls in one function and all the xxx.init() calls in one
> function

We can do more grouping, but we'd need to be sure we aren't doing it wrong (also for the future when things change). I don't know offhand the internals of all the actions here so I did quite a lot of splitting, probably more than is needed.

> * Can we just stop "pre-loading the content process? Do we even know if this
> helps?

I'm not sure how preloading the content process is related here? Are some of these actions dependent on the child process?

> * How can we open this mechaism up to add-ons? We could make the array of
> action use a "DelayedActions.register(aAction)" style helper object.

I like that idea. Something like an API for "do this action whenever you have time, no rush", and it makes sure to space out the actions enough to avoid lag?

Comment 8

[Wesley Johnston (:wesj)]

Attachment: Patch v1

This adds a DelayedStartupHandler object that you can register actions with. They're called at UIReadyDelayed.

On firstrun, a lot of time is taken to setting up form history. I added some logging. We can keep it in or remove it. Tried to split these up into groups of around 30ms. On my phone (a DroidX which hasn't had the file system problems we've seen on other phones) I see:

First start:
DelayedAction Load panel xbl bindings, event listeners, and observers(35ms)
DelayedAction Load login manager(28ms)
DelayedAction Load Form history(981ms)
DelayedAction Initialize Extension, Downloads, and Console views(37ms)
DelayedAction Initialize Sync(34ms)
DelayedAction Initialize helper objects(27ms)

Warmish start
DelayedAction Load panel xbl bindings, event listeners, and observers(39ms)
DelayedAction Load login manager(22ms)
DelayedAction Load Form history(27ms)
DelayedAction Initialize Extension, Downloads, and Console views(16ms)
DelayedAction Initialize Sync(26ms)
DelayedAction Initialize helper objects(19ms)

Note there's no actual history, forms history, logins, extensions, sync profile, etc installed here which could make some of these worse.

Comment 9

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

Bug 690903 is why FormHistory kills us on firstrun. I'd like to run this patch on some other devices too.

Comment 10

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

Also, I'd like to see if these changes affect tFirstPaint. Check the value in the error console.

Comment 11

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

Comment on attachment 563879 [details] [diff] [review]
Patch v1

>diff --git a/mobile/chrome/content/browser-ui.js b/mobile/chrome/content/browser-ui.js

>+    // Keep actions that perform file io as separate as possible

     // Keep startup actions chunked into smaller units of work

>+    DelayedStartupHandler.registerAction({
>+      desc: "Load panel xbl bindings, event listeners, and observers",

       desc: "Load panel XBL bindings, event listeners, and observers",

>+      run: function() {
>+        // load xbl bindings

// Load XBL bindings

>+        Elements.panelUI.hidden = false;
>+        // Listen tabs event

Add a blank line before comment

>+        }
>+        // Init helpers
>+        BadgeHandlers.register(BrowserUI._edit.popup);

Move this to the helpers group?

>+    DelayedStartupHandler.registerAction({
>+      desc: "Load login manager",

        desc: "Load LoginManager and FormHistory components",

Move the FormHistory init in here too. Once bug 690903 lands, it will be a lot less time consuming

>+    DelayedStartupHandler.registerAction({
>+      desc: "Initialize Extension, Downloads, and Console views",
>+      run: function() {
>+        // Init the tool panel views - these try to be smart and 

and... what?

>+      dump("DelayedAction " + action.desc + "(" + totalTime + "ms)");
>+      Services.console.logStringMessage("xxx: DelayedAction " + action.desc + "(" + totalTime + "ms)");

Remove the 'xxx' and use "DelayedAction: " for both

Wrap this in a #ifndef MOZ_OFFICIAL_BRANDING like here:
http://mxr.mozilla.org/mozilla-central/source/mobile/chrome/content/browser-ui.js#531

That way we get some timing data but only on nightly and aurora.

>+      this._timerId = setTimeout(this._processActions.bind(this), Math.max(totalTime*2, 50));

Do you need the _timerId? You never use it.
Does this totalTime * 2 thing matter? Using 50ms seems fine to me.

r-, but next one should be ready

Comment 12

[Wesley Johnston (:wesj)]

Attachment: Patch v2

Nits addressed.

Comment 13

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

Comment on attachment 564585 [details] [diff] [review]
Patch v2

Thanks. Let's give this a try

Comment 14

[Wesley Johnston (:wesj)]

http://hg.mozilla.org/integration/mozilla-inbound/rev/df94ebdc86fe

Comment 15

[Wesley Johnston (:wesj)]

Backed out because the entire world turned orange https://hg.mozilla.org/integration/mozilla-inbound/rev/00676a1337d0

Comment 16

[Sylvestre Ledru [:Sylvestre]]

Closing a Firefox for Android Graveyard bug