1120873 - Performance events of contacts app are fired before corresponding content has displayed on screen

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: Gaia::PerformanceTest, defect)

Description

[Patrick Wang (Chih-Kai Wang) (:kk1fff)]

The events that we use to measure app launch time (moz-chrome-interactive, moz-app-virually-complete and moz-content-interactive) are fired a bit earlier than the corresponding contents are displayed on screen. This could make the test result we measured not consistent with what is measured by other method (like captured directly from camera).

Comment 1

[Patrick Wang (Chih-Kai Wang) (:kk1fff)]

Attachment: Moving code that fires events into MozAfterPaint listener.

Simply moving the code that fires (marks) the event into MozAfterPaint can fix the problem. But normally MozAfterPaint is not exposed to Gaia, perhaps we will need to address this another way?

Comment 2

[Patrick Wang (Chih-Kai Wang) (:kk1fff)]

Had measured the latency of a MozAfterPaint's propagation from CompositorParent in parent to event handler in child, and it's about 60ms. But applying above patch makes visuallyloaded events fired only about 30ms later than original. This probably suggests that the MozAfterPaint event we handled is of the composition that has been done before we left the function that modifies DOM.

Comment 3

[Patrick Wang (Chih-Kai Wang) (:kk1fff)]

Since the actual change may not happen right at where content javascript can touch, I am thinking of proposing a new method in user timing API to provide more precise mark on specific events. The new method takes a target and a mark name as arguments, when the next time the target is hit, it marks with the given mark name. It may look like, for example, |performance.delayMark("composite", "visuallyloaded")|, and it means "mark visuallyloaded when next compositing happens". And we should be able to add more define the first parameter to provide a more target.

Eli, Kyle, do you have any thought? Thanks!

Comment 4

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

My version of the user timing api (bug 782751) hasn't finished review or landed yet, so I'll let Eli handle this.

Comment 5

[:Eli Perelman]

First, how long after triggering the performance markers does the screen update to reflect what the marker is implying?

Second, I'm not sure adding a new method to User Timing would solve anything here. What you want to achieve could be done with an event, just as you have, and triggering the marker at the correct moment.

Comment 6

[Patrick Wang (Chih-Kai Wang) (:kk1fff)]

(In reply to :Eli Perelman from comment #5)
> First, how long after triggering the performance markers does the screen
> update to reflect what the marker is implying?

It's around 50-80 ms, just an estimate value, since it's not easy to connect the performance mark to corresponding screen update.

The listener I add in the function which modifies DOM can be triggered by the composition that happened before the listener was added due to IPC latency between processes. The way I estimate the delay is to compare the delay of the event to the difference between current time and time when the listener was set, to make sure the event is corresponding to a composition done after the listener was set.
> 
> Second, I'm not sure adding a new method to User Timing would solve anything
> here. What you want to achieve could be done with an event, just as you
> have, and triggering the marker at the correct moment.

Since we don't know whether or not the MozAfterPaint we are handling in the listener is corresponding to the composition that puts our change onto the screen, and the event itself takes about 60 ms on flame to propagate to its handler. It's not easy to evaluate when does the update actually happen.

Comment 7

[:Eli Perelman]

Gandalf or Geo, do you have any thoughts here? I'm torn on this issue, and would like to get other opinions.

Comment 8

[Geo Mealer [:geo] -- This account is inactive after 2015-07-07]

If we were talking a frame or two I wouldn't worry at all. 60-80 is closer to 4-5 frames.

That said, we know there's a level of error here anyway because of the difference in a user-tap and how we launch. The intention is to -track- the value from camera testing, not be the same. Realistically, it's never going to be the exact same.

Strictly from a code analysis pov, is this gap likely to be unique to Contacts? Seems like if this is a "stage for draw" sort of lag, everything would have this problem. If so, maybe this is something we just call out as a general offset.

Comment 9

[:Eli Perelman]

I honestly don't think this would be unique to contacts.

Now that I think about it, I specifically crafted the definitions of these events to account for this scenario. From the definitions [1]:

> "...exists in the DOM and you have marked it as ready to be displayed..."

The purpose of the events is not to exactly match the triggering of the event with when the item is actually displayed, but as a marker for when they have been *marked* ready to display. There is a slight difference. While we wish they could be the same thing, and we should strive to make them so, each device and environment is going to be different, and we should understand that there could be a delay between the two. What's important is that the delay is consistent. If not, it should underline a problem.

Unfortunately I don't see a way around this unless we introduce more boilerplate code or something in Gecko to also emit markers at paints, which I don't foresee as being something scalable.

[1] https://developer.mozilla.org/en-US/Apps/Build/Performance/Firefox_OS_app_responsiveness_guidelines#Implementation

Comment 10

[Zibi Braniecki [:zbraniecki][:gandalf]]

As Eli mentioned in his last comment - the markers are supposed to mark when web app reports being ready for display/interaction, not when it actually happens.

I believe it is the right thing to do. 

First, wWe want to encourage optimizing code flow to be ready earlier, but web app developer has no way to alter internal engine's behavior to optimize the gap between "webapp reports being ready" and "engine displays".

Second, in my vision, the engine could use the markers to alter its own behavior better, for example:

 - "do not move app to foreground" or, "do not layout/paint" until moz-chrome-dom-loaded
 - "do not enable touch controls" until moz-chrome-interactive
 - "do not measure memory footprint" until moz-app-loaded
 - "do not take screenshot" until moz-app-visually-complete

This could save us from layout/reflow/painting before HTML/CSS is ready and from accidental touches before chrome is interactive.

For those two reasons I like that our markers are "from webapp", rather than "from engine". I would be happy to have counterparts for some of those events being reported by the engine:

 - first-paint happened
 - app-in-foreground-with-transition-finished
 - app-interactive

that would mark when engine executes operation like firstPaint. That would give you matching result to external observations.

Comment 11

[Patrick Wang (Chih-Kai Wang) (:kk1fff)]

(In reply to Zibi Braniecki [:gandalf] from comment #10)
> For those two reasons I like that our markers are "from webapp", rather than
> "from engine". I would be happy to have counterparts for some of those
> events being reported by the engine:
> 
>  - first-paint happened
>  - app-in-foreground-with-transition-finished
>  - app-interactive
> 
> that would mark when engine executes operation like firstPaint. That would
> give you matching result to external observations.

Recently I am implementing a performance test that measures the time it takes between receiving power key event and the first frame is drawn. It reminds me of this bug since we were discussing reporting markers from engine, which may be useful in implementing new test.

Since we are not changing API here and would mark from engine, I am thinking of an alternative way, that is each time when a marker is set from gaia, engine reports a mark when next paint is drawn. This won't require API change nor overwhelm the logcat, and will make us easier to figure out when the actual response is made. Any thoughts?

Comment 12

[:Eli Perelman]

I responded to Patrick via email, to summarize:

I'm not sure how to create performance markers from Gecko, but worst case scenario would be to output performance information through the log the same way Gecko does it. There is currently no mechanism for creating performance measures across processes; the best we have right now is associating a performance marker with another process via our "@" convention. Raptor will pick these up correctly and associate them, but it will not do a duration between any entries.

Comment 13

[Patrick Wang (Chih-Kai Wang) (:kk1fff)]

Thanks, Eli!

Just note that I've discussed with some people in Taipei team, and it looks like creating marks from Gecko might be useful for an app since it can use measure() to know the time it takes to paint its DOM modification programmatically.

Comment 14

[:Eli Perelman]

I'm going to close this bug as we have decided that Contacts is emitting markers correctly, they just wont correspond to actual paints. There is work towards enabling a performance marker interface in Gecko that will resolve the orthogonal issue.

https://bugzilla.mozilla.org/show_bug.cgi?id=1159639