871826 - Launch latency of Email application needs to be improved

Status: RESOLVED DUPLICATE of bug 892069

(Firefox OS Graveyard :: Gaia::E-Mail, defect, P2)

Description

[Mandyam Vikram]

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.64 Safari/537.31

Steps to reproduce:

We are seeing varying launch latencies (first time launch)for the Camera app over the last few releases (please see below). There seems to be a significant improvement in the last few builds. We would like to target improving this further (these numbers have been captured on a QRD device).


Actual results:

Here are some results captured over many weeks. 

Build                                      Launch time (ms)                          
QRD B2G AU01.01.00.19.050          3835
QRD B2G AU01.00.01.19.070          2983
QRD B2G AU01.01.00.019.077        3683
QRD B2G AU01.01.00.019.086        2460



Expected results:

We would like to see the launch time improved to ~2000 ms.

Comment 1

[Mandyam Vikram]

Is this being looked at? Thanks.

Comment 2

[Andreas Gal :gal]

Comment 0 says camera app, I assume that means email. Here its absolutely essential to get a very precise test case. We need to know what exactly is loaded in the email db to analyze this. Please post at least instructions how you filled the DB.

Comment 3

[Mike Lee [:mlee]]

Jon,
Please comment on where to find Email reference workloads and how to use them so @mvikram and others can use them when gathering and reporting performance numbers.

Comment 4

[Jon Hylands [:jhylands]]

Unfortunately, we don't reference workloads for email yet.

See Bug 840935 for details...

Comment 5

[Mandyam Vikram]

Have been working on capturing some details. Will provide updates soon.

Comment 6

[Mandyam Vikram]

Attachment: Email launch latency measurements

Here are our observations. 

We have enabled tracing within the email app and output it to Logcat (we can provide a patch that turns these traces on separately). Results are in the attached spreadsheet.

To begin with, here are the steps to reproduce the results captured:
1) Flash the build on the phone
2) On rebooting the phone, launch the email App
3) Configure the email account (we have two accounts as follows):
(Account with 86 emails):
username:[e-mail]
password:FFOSRocks

(Account with 1 email):
username:[e-mail]
password:GodBlessU

4) Exit the Email app
5) Launch "adb logcat | grep QCB2GTEAM" to capture trace information (assumes the build includes our patch)
6) Re-launch the Email app
7) Measure the time from the touch event to launch the app to when the first screen full of emails is painted

Please note that we also measured the launch time using a high speed camera to correlate these findings. On the average, the  camera launch latency is about ~2.2 secs.

Observations (Details in attached spreadsheet):

Summary:

                          Average launch time (ms) 
1 email                               2257.5
86 emails                             2336

Comment 7

[Michael Vines [:m1] [:evilmachines]]

(marking this bug qc confidential because I don't think we want gmail u/p in public bugs :) )

Comment 8

[Mandyam Vikram]

Any word on this? Thanks.

Comment 9

[Alex Keybl [:akeybl]]

We'll track for v1.1, we'll set koi? for v1.2 and we'll accept a low risk fix if found for v1.1.

Comment 10

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

We see a big difference of launch latency between AU01.01.00.019.102 and AU01.01.00.019.109.

Email app takes 2233 ms in AU01.01.00.019.102 and it takes 3419 ms in AU01.01.00.019.109 .


Can anyone tell us exact reasons for this regression? We see lots of changes in gaia email app itself between these two AUs.

We are measuring using camera (it has very high framerate).

Comment 11

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Tapas Kumar Kundu from comment #10)
> Email app takes 2233 ms in AU01.01.00.019.102 and it takes 3419 ms in
> AU01.01.00.019.109 .
> 
> Can anyone tell us exact reasons for this regression? We see lots of changes
> in gaia email app itself between these two AUs.

I don't know how to map from the provided identifiers to git hashes in the gaia repo or timestamps I could use to check the merge log.  Is there a place I can find out more information about how to map those id's?

James Burke has a prototype implementation that changes the e-mail app so that rather than caching our back-end wire protocol representation, we cache our HTML structure.  This allows us to take lazy loading to new heights.  Branch comparison (which is based off James' cleanup proposal branch):
https://github.com/jrburke/gaia/compare/master...groupload-htmlinabox

His runs estimate a 700-800ms mozilla time-to-load/"page load" number, which is of course a different metric than the high framerate camera metric used, but should represent an additional time-savings of at least 500ms.

Comment 12

[Andrew Sutherland [:asuth] (he/him)]

Also, can you just change the publicly exposed credentials in use in comment 6 so we can clear the confidential flag on this bug?

Comment 13

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

I changed password for email-ids given above. Please let us know if you need password. We can share it if needed

Comment 14

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

(In reply to Andrew Sutherland (:asuth) from comment #11)
> (In reply to Tapas Kumar Kundu from comment #10)
> > Email app takes 2233 ms in AU01.01.00.019.102 and it takes 3419 ms in
> > AU01.01.00.019.109 .
> > 
> > Can anyone tell us exact reasons for this regression? We see lots of changes
> > in gaia email app itself between these two AUs.
> 
> I don't know how to map from the provided identifiers to git hashes in the
> gaia repo or timestamps I could use to check the merge log.  Is there a
> place I can find out more information about how to map those id's?
> 
> James Burke has a prototype implementation that changes the e-mail app so
> that rather than caching our back-end wire protocol representation, we cache
> our HTML structure.  This allows us to take lazy loading to new heights. 
> Branch comparison (which is based off James' cleanup proposal branch):
> https://github.com/jrburke/gaia/compare/master...groupload-htmlinabox
> 
> His runs estimate a 700-800ms mozilla time-to-load/"page load" number, which
> is of course a different metric than the high framerate camera metric used,
> but should represent an additional time-savings of at least 500ms.

If we simply replace gaia email app folder from AU01.01.00.019.102 to AU01.01.00.019.109 then we see same old launch latency ( 2233 ms). This is same launch latency which we saw in AU01.01.00.019.102 .

So email app is showing bad launch latency (3419 ms) in  AU01.01.00.019.109 only because of changes in gaia email app.  I am confirming it here.

You can see all changes (related to this launch latency regression) if you simply make a |diff| between two gaia email app folder in both AU,  

Could you please tell us root cause of this regression in gaia email app itself and also solve this regression ?

Please note that we measure launch latency as time spent between touch down to rendering 1st page of emails. We measure it by High FPS camera. Our process of measurements includes all database activity.

Comment 15

[Andreas Gal :gal]

Faramarz, can you find out why this regressed, and why did our automation not catch this?

Comment 16

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Tapas Kumar Kundu from comment #14)
> If we simply replace gaia email app folder from AU01.01.00.019.102 to
> AU01.01.00.019.109 then we see same old launch latency ( 2233 ms). This is
> same launch latency which we saw in AU01.01.00.019.102 .
> 
> So email app is showing bad launch latency (3419 ms) in  AU01.01.00.019.109
> only because of changes in gaia email app.  I am confirming it here.
> 
> You can see all changes (related to this launch latency regression) if you
> simply make a |diff| between two gaia email app folder in both AU,  

I do not have access to any AU builds or to mappings between AU builds and gaia git hashes.  Please provide me with the git hashes of the gaia repo corresponding to your builds or a diff between the two builds as an attachment and I will be happy to try and look into the problem.

Comment 17

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

(In reply to Andreas Gal :gal from comment #15)
> Faramarz, can you find out why this regressed, and why did our automation
> not catch this?

Please let us know if we need to upload diff .

Comment 18

[James Burke [:jrburke]]

The diff would be helpful as we have no way to map AU01.01.00.019.102 and AU01.01.00.019.109 to actual commits to the gaia repo, which uses digests (like fc0ed1fb2a72327378946c2d6601c63eae31b718):
https://github.com/mozilla-b2g/gaia/commits/master

If you have the commit digests for those two AU numbers though, we could probably work out the diff ourselves.

Comment 19

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

Hi,

Gaia commit hash for 1.1 AU01.01.00.019.102 : b161f42c5647b37e35ba5a20f394ba40bf674d9c

You can compare it with Gaia commit hash for AU_LINUX_GECKO_ICS_STRAWBERRY.01.01.00.019.122 :1aed138dfef6279a00475f51ce0c491f32799ab6 .

Latest launch measurement by High FPS camera shows following result:
AU102 ===> Email App takes 2263 ms
Au122 ===> Email App takes 2600 ms

Regression happened only in gaia Email App. Please let us know what is creating this regression and solve it.

Comment 20

[Andrew Sutherland [:asuth] (he/him)]

Thanks for the hashes.  Based on the diff, my guess is that this is a combination of small things (another css file, increased JS code size) and the big thing is likely to be the changes to MailPeep/contact resolution which result in more busy-work even though the fundamental data dependency really shouldn't change.  James, it's probably a good idea if you see if anything else jumps out at you.

If we want to know for sure, someone would want to bisect or otherwise try 24e7b80f74e5784fa0fb643cc70de1de794d7509 or an earlier build right before the cached contact info changes.

I think the best solution to this is probably :jrburke's persistence of our HTML structure mentioned in comment 11.  It allows us to persist the HTML post-Contact lookup and should otherwise allow us to keep our camera-detected startup time relatively constant in the face of otherwise-bloating changes.  (We still need to worry about those for responsiveness reasons, of course.)

Comment 21

[James Burke [:jrburke]]

I just tried these two commits on my Unagi test device, using a b2g v1-train build generated yesterday (June 13, 2013):

b161f42c5647b37e35ba5a20f394ba40bf674d9c (for AU102)
1aed138dfef6279a00475f51ce0c491f32799ab6 (for AU122)

using a gmail account that has 4K of messages in its inbox (but of course not all are fetched). How I test:

* I configure the account in the New Account screen.
* I let the message list fully fetch, and I scroll to the top, waiting for all snippets to be received.
* I kill the app using the long press on the home button and clicking the X to close the app.
* I wait about 5 seconds, then I reopen the app. I measure the load time, kill the app again, wait 5 seconds, launch, time, repeat.

I use a digital hand timer, but I start and stop it with my other hand and I wait until I see some messages appear. I click stop when I see something show up in the message list.

This hand method is not a precise way to measure the times, but given that the difference being reported here is about 400ms, I expect to see some variation even with that imprecise method.

However, I consistently get 2.4 seconds with the first and second hashes. So, I am likely not testing the same thing as what is being reported. I also do not have any contacts installed for my test.

I put up the diff between those two hashes here:

https://gist.github.com/jrburke/85a05a65314b03e07768

Looking through it, nothing jumps out at me that would explain a 400ms difference. Some possibilities:

* The use of MessageListTopbar to indicate new messages. However, I would expect that be triggered after the cached data is shown.
* It includes the changes for defaultAccount, but those should be lightweight, just an account array scan (which is very short with one account) and a getter to find the default.
* An update to make sure contact information is up to date. This may be involved, but still digging into it more.

But I am really guessing, and I want to first be able to reproduce the time difference to make sure I am not chasing shadows, and that I can verify any changes I do to reduce any time difference.

The differences in the built gaia_build_defer_index.js files between the two versions is 156762 going to 165012, so added 8.3KB. Not enough to explain a 400ms difference.

I have seen slower times in the past if the email app has not been run for a while, and it thinks it should load the JS for the email protocols to check the network, but that usually is not a factor when doing multiple perf tests in a row.

Tapas Kumar Kundu: 

1) do you have the high speed videos saved so that I could view them? You can send it privately to me -- jburke at the mozilla.com domain. I want to be sure I am testing the same start and end conditions.

2) are there contacts configured on the device when these tests are run? My tests did not have any contacts, just the one gmail account configured in the email app.

Comment 22

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

(In reply to James Burke [:jrburke] from comment #21)
> I just tried these two commits on my Unagi test device, using a b2g v1-train
> build generated yesterday (June 13, 2013):
> 
> b161f42c5647b37e35ba5a20f394ba40bf674d9c (for AU102)
> 1aed138dfef6279a00475f51ce0c491f32799ab6 (for AU122)
> 
> using a gmail account that has 4K of messages in its inbox (but of course
> not all are fetched). How I test:
> 
> * I configure the account in the New Account screen.
> * I let the message list fully fetch, and I scroll to the top, waiting for
> all snippets to be received.
> * I kill the app using the long press on the home button and clicking the X
> to close the app.
> * I wait about 5 seconds, then I reopen the app. I measure the load time,
> kill the app again, wait 5 seconds, launch, time, repeat.
> 
> I use a digital hand timer, but I start and stop it with my other hand and I
> wait until I see some messages appear. I click stop when I see something
> show up in the message list.
> 
> This hand method is not a precise way to measure the times, but given that
> the difference being reported here is about 400ms, I expect to see some
> variation even with that imprecise method.
> 
> However, I consistently get 2.4 seconds with the first and second hashes.
> So, I am likely not testing the same thing as what is being reported. I also
> do not have any contacts installed for my test.
> 
> I put up the diff between those two hashes here:
> 
> https://gist.github.com/jrburke/85a05a65314b03e07768
> 
> Looking through it, nothing jumps out at me that would explain a 400ms
> difference. Some possibilities:
> 
> * The use of MessageListTopbar to indicate new messages. However, I would
> expect that be triggered after the cached data is shown.
> * It includes the changes for defaultAccount, but those should be
> lightweight, just an account array scan (which is very short with one
> account) and a getter to find the default.
> * An update to make sure contact information is up to date. This may be
> involved, but still digging into it more.
> 
> But I am really guessing, and I want to first be able to reproduce the time
> difference to make sure I am not chasing shadows, and that I can verify any
> changes I do to reduce any time difference.
> 
> The differences in the built gaia_build_defer_index.js files between the two
> versions is 156762 going to 165012, so added 8.3KB. Not enough to explain a
> 400ms difference.
> 
> I have seen slower times in the past if the email app has not been run for a
> while, and it thinks it should load the JS for the email protocols to check
> the network, but that usually is not a factor when doing multiple perf tests
> in a row.
> 
> Tapas Kumar Kundu: 
> 
> 1) do you have the high speed videos saved so that I could view them? You
> can send it privately to me -- jburke at the mozilla.com domain. I want to
> be sure I am testing the same start and end conditions.

I will upload email launch video here soon. It is the duration between touch down to rendering 1st page of emails. 
> 
> 2) are there contacts configured on the device when these tests are run? My
> tests did not have any contacts, just the one gmail account configured in
> the email app.

Our device has 200 contacts configured. Can you please confirm whether contact app can delay email launch or not ? My understanding is contact and email app runs independently. So contact app should not affect email launch. I can share with you email id and password (if you need) which I used to testing.

Comment 23

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

Attachment: Email launch video taken using High FPS camera

This is the Email launch video taken by high FPS camera. This is for AU_LINUX_GECKO_ICS_STRAWBERRY.01.01.00.019.122. The video is compressed to meet 10MB upload limit in bugzilla.

Comment 24

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

Please let us know if you need any more information.

Comment 25

[James Burke [:jrburke]]

I did a profile.sh trace of the app, related to 886446, and noticed in that profile capture that ContactCache.resolvePeep/handleResult took 61 ticks at a 10ms sampling, which I believe works out to be about 600ms. So my current suspicion is that it is likely related to the querying of the Contacts API to get contact data for people listed in the MailHeaders -- that and/or the subsequent updates to the DOM as a result of it.

That work seems to show up around the pushCard call to push the HTML for the message list into the DOM. So I want to experiment with first shutting off the Contacts API use in resolvePeep to see how that performs, and possibly look at delaying that work until later, after card display is done.

If you are curious about trying some experiments yourself in this area, perhaps shutting off the use of contactsAPI.find() here:

https://gist.github.com/jrburke/85a05a65314b03e07768#file-870320-diff-L994

Comment 26

[Mike Lee [:mlee]]

Andrew and James, who's actually working on this? Which one of you should this be assigned to?

Comment 27

[James Burke [:jrburke]]

Even though this is an earlier bug, marking as duplicate for 892069, which is marked fixed on gaia master. That bug included a final round of speedups and only loading the correct start card for activity actions, so startup should be now at acceptable levels.