1024005 - Gaia Email App Startup Time Regression

Status: RESOLVED WORKSFORME

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

Description

[Mason Chang [Inactive] [:mchang]]

Bug 1018534, created an email FTU regression of ~20-30ms.

Comment 1

[Mason Chang [Inactive] [:mchang]]

Tip
Results for Email, cold_load_time: median:623, mean:627, std: 28, max:732, min:581, all:657,636,622,621,647,613,581,633,625,643,632,606,623,596,612,639,603,633,664,615,614,592,617,732,633
Results for Email, cold_load_time: median:622, mean:633, std: 39, max:724, min:578, all:682,610,643,608,724,609,623,692,626,617,640,616,596,578,581,637,674,602,633,622,603,723,616,615,679
Results for Email, cold_load_time: median:616, mean:623, std: 28, max:704, min:576, all:659,669,626,611,593,608,614,660,634,614,620,601,704,604,616,616,622,628,576,579,624,613,604,661,638


moz-central backout 1014410, gaia tip
Results for Email, cold_load_time: median:628, mean:639, std: 36, max:711, min:581, all:661,625,640,688,613,610,628,637,598,655,637,697,619,634,581,702,711,625,657,610,602,606,620,711,627
Results for Email, cold_load_time: median:629, mean:636, std: 30, max:701, min:592, all:642,643,642,620,605,627,592,651,683,613,648,612,701,618,682,698,690,614,607,629,628,629,598,614,637
Results for Email, cold_load_time: median:619, mean:627, std: 30, max:703, min:592, all:651,614,624,608,601,696,598,699,619,612,606,625,656,620,592,652,703,613,626,624,602,608,612,612,620

Gaia 1018534 back out
Results for Email, cold_load_time: median:608, mean:624, std: 40, max:692, min:577, all:615,638,631,594,679,590,605,659,682,581,619,583,686,608,577,598,593,678,591,688,580,600,692,669,587
Results for Email, cold_load_time: median:591, mean:598, std: 25, max:665, min:571, all:625,593,581,594,576,594,584,571,623,577,577,603,612,579,585,665,664,591,603,629,614,581,579,579,573
Results for Email, cold_load_time: median:602, mean:601, std: 25, max:661, min:564, all:649,625,625,583,567,580,620,606,593,629,591,564,570,631,605,607,602,573,586,578,578,592,614,661,618

Gaia: f5466f4
Gecko: 187866:13be61241671

Comment 2

[Mason Chang [Inactive] [:mchang]]

Anything we can do about this?

Comment 3

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

Do we think it's a question of permission check costs?  Like say there's a fast-path for certified apps since we can say "yes" almost instantly but for privileged we need to round-trip the lookup/etc.?  If so, that would imply this is a platform bug that is meaningful since it would be slowing down all apps and putting non-built-in apps at a disadvantage.  And I suppose the email mitigation would be to touch less things that trigger permission checks during the startup path.

Comment 4

[Mason Chang [Inactive] [:mchang]]

I'm not really sure. James thought backing out 1014410 on the platform might help, but that didn't change anything. Vivien, do you know the answer to comment 3? Thanks!

The other thing I see in the commit is the acceptContactsPermission. This might be invoked when the app is started and that's why the regression comes?

Comment 5

[James Burke [:jrburke]]

I tried with the template app, which is really basic, some results:

template app: type="certified";
Results for Template, cold_load_time: median:456, mean:451, std: 38, max:501, min:266, all:266,501,484,481,471,442,467,462,468,432,458,455,463,468,445,465,485,446,440,455,450,447,460,431,461,444,434,454,438,472

template app: type="privileged", no permissions section:
Results for Template, cold_load_time: median:456, mean:455, std: 31, max:502, min:314, all:314,487,464,467,445,454,455,450,466,437,440,451,469,458,461,450,466,449,450,475,483,434,480,499,443,466,426,452,482,502

template app: type="privileged", permissions: all same as email:
Results for Template, cold_load_time: median:458, mean:461, std: 42, max:567, min:276, all:276,456,494,489,465,457,458,441,489,477,455,450,456,480,464,473,450,450,472,486,436,506,475,567,456,459,452,462,448,452

So no built in cost to just the type setting. I also tried with the email app by reducing the number of "permissions" entry to just "storage":{}, "device-storage:sdcard":{ "access": "readcreate" }, but no difference in timings.

So current state of a guess at the end of today is that the actual use of the APIs incurs some extra cost now. Have not narrowed it down further though, just reporting what data was gathered so far.

Comment 6

[[:fabrice] Fabrice Desré]

Certified apps have a fast path CSP checker that we don't use for privileged apps. That likely explain the slowdown you see here.

Comment 7

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

(In reply to Mason Chang [:mchang] from comment #4)
> I'm not really sure. James thought backing out 1014410 on the platform might
> help, but that didn't change anything. Vivien, do you know the answer to
> comment 3? Thanks!
> 
> The other thing I see in the commit is the acceptContactsPermission. This
> might be invoked when the app is started and that's why the regression comes?

What Fabrice says. It would be easy to double check that this is related to CSP by simply turning it off (security.csp.enable = false) in the prefs.

Comment 8

[James Burke [:jrburke]]

More time capture, median times:

1) privileged: 663
2) privileged with user_pref("security.csp.enable", false): 623
3) certified: 645
4) certified with user_pref("security.csp.enable", false): 623
5) privileged, with no calls to mozContacts: 671
6) privileged, using cookie cache: 677

Disabled CSP helps both the certified and privileged cases. 

5) was testing if not accessing mozContacts on startup would positively affect the time, but I believe what happened is that the non-mozContacts paths just executed the code that would have been in a contacts API callback immediately, resulting in more up front execution.

When looking at the logs during the tests, the cookie cache was not being used, it was not getting set before the app was shut down. So for 6) I opened the app one time to generate the cache, then ran the tests.

The cache route loads a small JS file, synchronously injects HTML that references images, then starts the load of the rest of the JS.

The email app now emits the startup events for logging, which capture the different states better than this metric might, so those are probably the better numbers to look at over the long haul.

Since bug 1027185 will switch the email app's manifest back to certified for other reasons, that will also likely moot this bug, and I will it when the other bug lands. Hopefully that will also give us a historical base for the startup event numbers if we do switch email back to priviliged.

---

Raw data, run on a hamachi:

Gaia      eac13407742a55b11e1877b4df2abdfd22cd582e
Gecko     https://hg.mozilla.org/mozilla-central/rev/bb35d1b73634
BuildID   20140617040203
Version   33.0a1
ro.build.version.incremental=324
ro.build.date=Thu Dec 19 14:04:55 CST 2013

Email from: git commit b889fdf33a15440eaab9253ab845543126956a7f

To push each change: make GAIA_OPTIMIZE=1 NOFTU=1 reset-gaia

b2gperf --delay=10 --reset --iterations=30 E-Mail

privileged:
Results for E-Mail, cold_load_time: median:663, mean:659, std: 41, max:730, min:474, all:474,696,663,676,661,673,655,646,660,621,730,672,704,672,668,692,615,642,653,679,663,676,659,683,662,679,665,661,663,623


privileged with user_pref("security.csp.enable", false):
Results for E-Mail, cold_load_time: median:623, mean:629, std: 64, max:867, min:405, all:405,657,603,656,630,622,614,656,606,629,623,645,867,622,600,649,613,638,623,614,654,722,630,611,604,620,593,624,630,619

certified:
 Results for E-Mail, cold_load_time: median:645, mean:647, std: 47, max:756, min:466, all:466,701,645,646,620,673,643,657,652,642,632,654,739,708,636,636,614,657,611,650,632,688,635,653,626,756,637,649,621,652

certified with user_pref("security.csp.enable", false):
Results for E-Mail, cold_load_time: median:623, mean:619, std: 44, max:707, min:408, all:408,664,627,624,600,624,610,626,614,623,595,615,707,616,618,640,598,601,621,627,623,622,640,645,607,621,633,624,659,640

privileged, with no calls to mozContacts
Results for E-Mail, cold_load_time: Results for E-Mail, cold_load_time: median:671, mean:677, std: 54, max:854, min:475, all:475,710,664,678,654,670,655,664,687,726,657,719,666,696,658,854,666,671,675,760,657,685,651,672,666,684,653,677,709,680

privileged, using cookie cache
Results for E-Mail, cold_load_time: median:677, mean:683, std: 56, max:782, min:457, all:457,725,653,693,778,685,676,677,643,667,668,744,674,707,682,662,662,678,680,663,682,705,654,673,677,681,651,782,762,761

Comment 9

[James Burke [:jrburke]]

Email app back to being certified. Closing this out. Future comparisons with app startup events likely a better gauge to consider perf impact if privileged is considered in the future.

Comment 10

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

(cleaning up email wontfix bugs: setting this to WFM since we resolved the problem by backout.  invalid might also work.)