924032 - ~40ms delay from app.launch to mozChromeEvent

Status: RESOLVED FIXED

(Core Graveyard :: DOM: Apps, defect, P1)

Description

[Kevin Grandon :kgrandon]

We are noticing a delay ranging from 20 to 40ms when launching an app. I measured this from directly calling the launch() method of an app, until the system app receives the webapps-launch mozChromeEvent.

40ms seems like an insanely long time to bubble this event, so we should see if we can do this faster.

Comment 1

[Kevin Grandon :kgrandon]

Hi Vivien, Fabrice - Wondering if you guys would know who could best look into this issue. I'm not sure what an acceptable range here is, but I would hope that the system app could receive this event in < 5ms after being called.

Comment 2

[[:fabrice] Fabrice Desré]

I will take a look, since 40ms seems really too long.

Note that it's not just bubbling an event though: we do an ipc call to the parent, find the localized launched path, and then send back an observer notification to shell.js that finally dispatch the mozChromeEvent.

Comment 3

[[:fabrice] Fabrice Desré]

Attachment: wip

This patch has a small gecko optimization, but it doesn't help a lot overall. Here's a sample launch of the settings app: The total time from calling launch() to getting the webapps-launch chrome event is 46ms, but we dispatch the event from gecko after 13ms.
So we spend more than 30ms dispatching to the event listener. Since event dispatching is synchronous, the one from AppWindowFactory may be late in the chain and so has to wait for the other ones doing something. I'll give it a try at reordering the listeners to move this one in front.


I/GeckoDump( 2728): XXX launch roundtrip: 3ms. (started at 1381261243849, now is 1381261243852)
I/GeckoDump( 2728): XXX launch roundtrip 2: 5ms. now is 1381261243854
I/GeckoDump( 2728): About to sendEvent webapps-launch 1381261243857
I/GeckoDump( 2728): About to dispatch webapps-launch 1381261243859
E/GeckoConsole( 2728): Content JS LOG at app://system.gaiamobile.org/js/app_window_factory.js:43 in awf_handleEvent: Got webapps-launch: 1381261243892
E/GeckoConsole( 2800): Content JS LOG at app://homescreen.gaiamobile.org/gaia_build_defer_index.js:119 in pg_tap: Launching app: 1381261243846

Comment 4

[Kevin Grandon :kgrandon]

Awesome investigation Fabrice. Just clearing Vivien's flag here.

Comment 5

[[:fabrice] Fabrice Desré]

So, we are actually being slowed down by the amount of mozChromeEvent handlers registered before reaching the one that manages webapps-launch (in system/js/app_window_factory.js). I did a quick and dirty experiment changing this event to be "webapps-launch" instead (whit the match gecko change) and we go down from 30ms to < 5ms.

I think that app launching performance is important enough to warrant its own event there. I'll post a patch tomorrow if there are no objections.

Comment 6

[Kevin Grandon :kgrandon]

Fabrice, this sounds excellent. Thank you for the investigation!

We should investigate and see if there is other performance critical areas where we should use their own events instead of mozChromeEvents, and get a better understanding of what the tradeoff is.

Comment 7

[[:fabrice] Fabrice Desré]

Attachment: patch

Gecko part: not using a chrome event anymore, and doing the simple payload wrapping manually to not waste cycles.

Comment 8

[[:fabrice] Fabrice Desré]

Attachment: gaia patch

Switching to the new event.

Comment 9

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

(In reply to Fabrice Desré [:fabrice] from comment #5) 
> I think that app launching performance is important enough to warrant its
> own event there. I'll post a patch tomorrow if there are no objections.

I can only agree here.

Comment 10

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 814633 [details] [diff] [review]
gaia patch

Review of attachment 814633 [details] [diff] [review]:
-----------------------------------------------------------------

::: apps/system/js/app_window_factory.js
@@ +33,5 @@
> +          if (!config.manifest)
> +            break;
> +
> +          this.publish('launchapp', config);
> +          break;

In order to not have to do that for this case and the mozchromeevent case, let's move the code that handle applicationready directly as:

var self = this;
window.addEventListener('applicationready', function onApplicationReady(e) {
  window.removeEventListener('applicationready', onApplicationReady);
  window.addEventListener('mozChromeEvent', self);
  window.addEventListener('webapps-launch', self);
});

and then you can do this code inside at the top level stuff of handleEvent.

Comment 11

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

(In reply to Vivien Nicolas (:vingtetun) (:21) from comment #9)
> (In reply to Fabrice Desré [:fabrice] from comment #5) 
> > I think that app launching performance is important enough to warrant its
> > own event there. I'll post a patch tomorrow if there are no objections.
> 
> I can only agree here.

Thinking about it a second time I think you also want a fast path for shell.openAppForSystemMessage in order to not slow down alarms and activity as well.

Comment 12

[Kevin Grandon :kgrandon]

Comment on attachment 814633 [details] [diff] [review]
gaia patch

Review of attachment 814633 [details] [diff] [review]:
-----------------------------------------------------------------

Since Vivien had some concerns, I'll let him take the review.

My only nit would be that  I think we should handle all of these messages the same way, either creating an event for each, or using a single mozChromeEvent listener in the system app. I have no problem trying to clean this up in the future though.

Comment 13

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

(In reply to Kevin Grandon :kgrandon from comment #12)
> Comment on attachment 814633 [details] [diff] [review]
> gaia patch
> 
> Review of attachment 814633 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Since Vivien had some concerns, I'll let him take the review.
> 
> My only nit would be that  I think we should handle all of these messages
> the same way, either creating an event for each, or using a single
> mozChromeEvent listener in the system app. I have no problem trying to clean
> this up in the future though.

Yeah we spoke with Fabrice yesterday and he kind of think that we should one event for each in b2g/shell.js. Having an overhead because of the number of event handlers is not nice. An alternative that he does not like too much is having one chrome event that is handle by one method in the system app that converts it to custom events.

So at the end there will be only one way, either a mozChromeEvent that is converted in the system app, or multiple events from b2g/shell.js.

In bug 925115 Alive seems to need the launch event to be accessible to the homescreen app, I was also wondering if we can not send it directly the launch event on the mgmt part of the mozApps API but it's hard to find use cases for that.

Comment 14

[[:fabrice] Fabrice Desré]

Attachment: gecko patch v2

Updated to convert the 3 events used in app_window_factory.js

Comment 15

[[:fabrice] Fabrice Desré]

Attachment: gaia patch v2

Matching gaia patch.

Comment 16

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 815522 [details] [diff] [review]
gecko patch v2

Review of attachment 815522 [details] [diff] [review]:
-----------------------------------------------------------------

r+ but I won't be against a shell.sendCustomEvent('event-name', payload) which does wrapping itself.

Comment 17

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 815523 [details] [diff] [review]
gaia patch v2

Review of attachment 815523 [details] [diff] [review]:
-----------------------------------------------------------------

::: apps/system/js/app_window_factory.js
@@ +20,5 @@
> +        window.addEventListener('applicationready', function appReady(e) {
> +          window.removeEventListener('applicationready', appReady);
> +          window.addEventListener('webapps-launch', self);
> +          window.addEventListener('webapps-close', self);
> +          window.addEventListener('open-app', self);

Let's keep Alive Todo about the homescreen singleton.

@@ +41,3 @@
>  
> +      switch (evt.type) {
> +        case 'webapps-launch':

nit: let's keep the TODO, it has probably been inserted here by Alive.

@@ +58,5 @@
> +          config.changeURL = !detail.onlyShowApp;
> +          config.stayBackground = !detail.showApp;
> +          // TODO: Create activity window instance
> +          // or background app window instance for system message here.
> +          this.publish('launchapp', config);

If you want to be sneaky you can move 'case open-app': above the 'case webapps-launch': and avoid to break. That will share this part and the comment.

But I know some people don't like that...

Comment 18

[[:fabrice] Fabrice Desré]

In order to not break tests, I will land this patch with the following steps:
- land gecko patch to add the new event, but keeping the old one for now.
- once it's on m-c and travis has updated gecko, land the gaia PR.
- once the gaia fix has migrated to tbpl, land a gecko followup to remove the old event.

So dear sheriffs, don't resolve as fixed until this is all done ;)

Comment 19

[[:fabrice] Fabrice Desré]

Gecko patch 1:
https://hg.mozilla.org/integration/b2g-inbound/rev/40ea83931670

Comment 20

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/40ea83931670

Comment 21

[[:fabrice] Fabrice Desré]

Reopening to finish what I said in comment 18.

Comment 22

[[:fabrice] Fabrice Desré]

Pushed gaia bits after green Travis run:
https://github.com/mozilla-b2g/gaia/commit/2b10e0af4c96568a2726f09d17b549e6608f83ff

Comment 23

[Kevin Grandon :kgrandon]

Noming as the parent bug blocks a blocker. Also removing regression as I don't believe this was ever a regression.

Comment 24

[[:fabrice] Fabrice Desré]

https://hg.mozilla.org/integration/b2g-inbound/rev/7ecc058d0317

Comment 25

[Andrew Overholt [:overholt]]

koi+ due to blocker chain

Comment 26

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/7ecc058d0317

Comment 27

[Ryan VanderMeulen [:RyanVM]]

I'm going to leave the v1.2 uplifts to you, Fabrice.

Comment 28

[[:fabrice] Fabrice Desré]

Patch 1 on aurora:
https://hg.mozilla.org/releases/mozilla-aurora/rev/a73aa637d09f

Comment 29

[John Ford [:jhford] CET/CEST Berlin Time]

v1.2: d812397765769e6319e15af11ba01f4c7feaa211

Comment 30

[[:fabrice] Fabrice Desré]

https://hg.mozilla.org/releases/mozilla-aurora/rev/ed279034d066

Comment 31

[Tim Guan-tin Chien [:timdream] (please needinfo)]

I wonder if this patch would make AppWindowFactory misses |open-app| event sent before it is being loaded, since we did not wait for isHomeLoaded (Bug 793082)?

Comment 32

[[:fabrice] Fabrice Desré]

(In reply to Tim Guan-tin Chien [:timdream] (MoCo-TPE) (please ni?) from comment #31)
> I wonder if this patch would make AppWindowFactory misses |open-app| event
> sent before it is being loaded, since we did not wait for isHomeLoaded (Bug
> 793082)?

I think you're right. We don't buffer in sendCustomEvent() and sendEvent() and we should to be 100% race free.