825137 - Provide a reliable way to measure app startup time

Status: RESOLVED DUPLICATE of bug 996038

(Firefox OS Graveyard :: Gaia, defect)

Description

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

The way we currently measure startup time for apps is by taking it's firstPaint. On top of that we can easily read Gecko's Performance API timings to get numbers timings for DOMContentLoaded or document.loaded.

While those timings hold significant correlation with app startup time, they are not related to any of the timings that have actual importance to the UX. In particular:

 - the time between initializing app launching and the moment when the screen is drawn and its content is drawn.
 - the time between app launching initialization and the moment when the app becomes responsive.

For quite some time I'm mostly using firstPain with combination with the API mentioned above to factor the stages of app loading and the cost that they carry.

Today I recorded cold boot timings on HFR camera (240fps) and tried to apply those numbers onto the ones from firstPaint or Perf API. They're hardly related.

Examples:

Browser app:
 - firstPaint: 259ms

Timing from the camera (from touching till last image loaded): ~2000ms.

Settings app:
 - firstPaint: 1681ms
 - DOMContentLoaded: 1100ms
 - document.loaded: 1193ms

Timing from the camera (from touching till background activation): ~2300ms.


Template app:
 - firstPaint: 926ms
 - DOMContentLoaded: 520ms
 - document.loaded: 530ms

Timing from the camera (from touching till background activation): ~1250ms.

I took the browser numbers to confirm my feeling that browser and settings boot time is much closer than firstPaint number suggest.

Now, there are multiple stages of the app booting:
1) the icon is pressed initializing app launch
2) the app zooming in animation appears providing user a feedback to his action
3) the zooming in is complete - either screenshot from app state or blank background is visible
4) the app is becoming visible
5) the app's UI (buttons etc.) are becoming "active"
6) the app brightness/saturation jumps to max to indicate that the app is ready to be used.

It feels to me that using firstPaint is misleading and we should at least get 1-to-6 and possibly 1-to-4 in order to be able to better identify slowdowns.

Comment 1

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

video url: http://dl.dropbox.com/u/355217/gaia-apps-boot-240fps-dec20

Comment 2

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

Attachment: Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7578

this measures the time between appwillopen event and mozbrowserloadend.

We could do even better by measuring from the moment of tap event registered, until mozbrowserloadend, but that would require addition event to be fired on tap somewhere here: https://github.com/mozilla-b2g/gaia/blob/master/apps/homescreen/js/page.js#L626

Comment 3

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

This already gives much more realistic timings than the currently used firstPaint (which often fires way before the app is actually loaded)

Comment 4

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

Comment on attachment 702640 [details]
Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7578

Please update the commit message and squash your commits.

Comment 5

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

(In reply to Vivien Nicolas (:vingtetun) (:21) from comment #4)
> Comment on attachment 702640 [details]
> Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/7578
> 
> Please update the commit message and squash your commits.

Squashed and updated

Comment 6

[Kevin Grandon :kgrandon]

Landed: https://github.com/mozilla-b2g/gaia/commit/164c733ce4b1c52b8c6b0e0a932fb718f3acdba2

Comment 7

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

I started comparing ttlview numbers with camera readings.

Procedure:
 - I loaded today's B2G with latest patch from bug 819000
 - I loaded latest gaia and turned on ttlview
 - I retested cold boot of each app 5 times
 - I then started recording using GoPro Hero3 camera
 - restarted the phone via "adb reboot"
 - measured system startup and respective app startup, killing each app after starting it
 - compared the numbers from ttlview with video
 - I measured each app from the 0.1s when the tap happened (which changes icon's background) till the moment when the app "brightens" which indicates that the app is ready and active.

The granularity of my readings is around 100ms because that's how fast VLC time extension goes (which I used to read milliseconds).

System boot, camera reading: ~37.2s

           ||   ttlview   ||   camera    ||  delta
===========||=============||=============||=========
Dialer     ||    1399     ||    1600     ||  +200ms
SMS        ||    1279     ||    1400     ||  +100ms
Contacts   ||    2573     ||    2700     ||  +100ms
Browser    ||    1158     ||    1400     ||  +200ms
Template   ||     544     ||     800     ||  +200ms
Settings   ||    2145     ||    2800     ||  +600ms
Calendar   ||    1871     ||    1900     ||     0ms
Email      ||    5073     ||    5100     ||     0ms

The 100-150ms difference matches the time between tap event and when we start registering timer for ttlview, so we can get closer if we fix that.

Usually in my recording the ttlview number showed up within 100ms to when the screen brighten except of a few anomalies:

 - Settings: The ttlview showed up 400ms before the screen brighten and even then the screen stayed empty for another 1000ms when finally the startup transition screen got shown.
 - Browser: the app background and layout has been displayed for over 100ms before right-top icon and page text got onto the screen
 - Calendar: the text and graphics showed up 700ms later than the screen brighten (and for those 700ms it stayed white)

It seems that for most cases ttlview is reliable and we can improve it by measuring from tap event instead from appwillopen. It should be an easy fix.

For the outliers, I don't think we can do too much to measure that from within of ttlview. Settings has a start transition which probably interferes with window opening transition but that's beyond our measurement capabilities.
Calendar worries me and I'm wondering if that can be that JS combination has anything to do with this.

Comment 8

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

Updated data ttlview vs. camera

           ||   ttlview   ||   camera    ||  delta
===========||=============||=============||=========
System     ||             ||   36200     ||
Dialer     ||     861     ||    1100     ||  +200ms
SMS        ||    1194     ||    1300     ||  +100ms
Contacts   ||     868     ||    2600     ||  +1700ms
Browser    ||    1027     ||    1600     ||  +500ms
Template   ||     339     ||     500     ||  +100ms
Settings   ||    1149     ||    1300     ||  +100ms

Notes:
* There is a 1000ms lag between clicking screen unlock and the transition to home screen
* Settings app has two additional time points - GPS switches on 900ms after the app is fully visible, and then subtitles for Cellular & Bluetooth show up another 2100ms later
* Contacts app has an additional flicker within those 2600ms. Sequence looks like this (time since tap):
 - tap: 0
 - ttlview shows up: 1100ms
 - screen lightens: 1800ms
 - first icons show up: 2200ms
 - UI switch to intro text: 2400ms
 - new icons for intro text show up: 2600ms

when the intro is not used (contacts exist in the address book) the screen still flickers by first displaying empty list and then adding items (although the items are there in the screenshot displayed during startup) and the whole startup takes still around 2400ms, instead of 868 shows by the ttlview.

Comment 9

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

filed bug 843852 and bug 843855 for Browser and Unlock screen respectively.

Comment 10

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

and bug 843863 for Settings

Comment 11

[Dietrich Ayala (:dietrich)]

Gandalf, is there anything actionable here?

Comment 12

[Diego Marcos [:dmarcos]]

In the case of the camera I would like to provide a test that measures the startup time that the user actually perceives. The number below doesn't provide the whole picture:

https://datazilla.mozilla.org/b2g/?branch=master&device=hamachi&range=7&test=cold_load_time&app_list=browser,camera&app=camera&gaia_rev=cd8a439bedf516cb&gecko_rev=2ce082378fcad0d0
e. 

For the camera, startup time is the period between the user tapping the icon and the moment when the app is ready to take a picture. In a hamachi the camera app takes more than 3 seconds to be ready and the hardware initialization time dominates (more than 2 seconds).

How can I produce a test that gets integrated in datazilla so everybody can keep an eye on the number? 

It would be even more useful if as part of the test we can provide not just a number but also a break down of the time showing where we spend time. A test could emit several events with timestamps that could be aggregated on a stacked bar plot like the one below:

http://jbkflex.files.wordpress.com/2012/01/stacked_chart.jpg

Comment 13

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

I didn't have time recently to work on that, but I believe that there's a potential to refactor the communication between the system and the app to give us better control over the process, and get more reliable tickers for app loading than the currently used window.load event (which results in a temptation to move startup path code past window.load to get a good looking numbers in datazilla :/)