1072500 - [Flame][KK] The time to start up camera from lockscreen is regressed compared to 2.0 because of FMD

Status: VERIFIED FIXED

(Firefox OS Graveyard :: FindMyDevice, defect)

Description

[No-Jun Park [:njpark]]

STR:
Open browser, go to www.marketwatch.com and wait until it loads
When the site is fully loaded, lock the screen by pressing the power button
Press power button again to wake up.  Slide to the camera side

Expected: the camera app should start up in the same time it took for 2.0 build

Actual: in 2.2 master branch, it takes about 3 seconds more for the phone to display the active viewfinder.
https://www.dropbox.com/s/bes88foz075vpy0/VID_20140924_150551.mp4?dl=0

This is probably not the camera bug, but related to something more basic.  Feel free to change the component as you see fit.

Version Info:
Gaia-Rev        ff6dbb006e4e60edba697639aa2a2a199b07069b
Gecko-Rev       https://hg.mozilla.org/mozilla-central/rev/1e2993c99323
Build-ID        20140924040205
Version         35.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20140924.071955
FW-Date         Wed Sep 24 07:20:05 EDT 2014
Bootloader      L1TC10011800

Comment 1

[No-Jun Park [:njpark]]

In the video, left is 2.0 device, and right is 2.2.  Both has 319MB of ram, on v180 KK base image.

Comment 2

[No-Jun Park [:njpark]]

Here are some additional videos.  In following 3 videos, I compared 2.0 and 2.1 time.  Both were in KK v180 base image.

Version Info:
(2.0)
Gaia-Rev        ddb7567c60b31dbcb27817f8c126bbba8dccb63b
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/e3545ca967ae
Build-ID        20141001000205
Version         32.0
Device-Name     flame
FW-Release      4.4.2

(2.1)
Gaia-Rev        86a3626055ed58b39525424126870dc0a503e79f
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-aurora/rev/c20912812877
Build-ID        20141001000202
Version         34.0a2
Device-Name     flame
FW-Release      4.4.2

Comparing the reboot time (left is 2.0, right is 2.1)
https://www.dropbox.com/s/1d2j8fju2k6h10m/20vs21_reboot.mp4?dl=0

Comparing the camera bootup time, when no apps are running on background:
https://www.dropbox.com/s/l5skiyhnytmafy4/20vs21_camera_noapp.mp4?dl=0

Comparing the camera bootup time, when the browser app is running on background:
https://www.dropbox.com/s/2tfl65wc2am7ndw/20vs21_camera_browserbackground.mp4?dl=0

Looks like overall, 2.1 speed has regressed about 1~2 seconds compared to 2.0

While doing the regressionwindow check, we should compare it from 2.1 instead of master branch to save time.

Comment 3

[Jayme Mercado [:JMercado] (Inactive 3/4/2016)]

I attempted to find a regression window for this issue, but  instead of a definitive broken/not broken state it is more of a gradual decline in performance.  I found two builds where I considered the last to be acceptable and the next to be unacceptable but the pushlog yielded results that were all from fx-team instead of one of the inbounds.  That information is below if it helps.

Last Working 
Environmental Variables:
Device: Flame 2.1
BuildID: 20140816031614
Gaia: 5e37ce8c7f0bf6992911d77eb31513db37656aba
Gecko: 675bab72b8a8
Version: 34.0a1 (2.1) 
Firmware Version: L1TC00011230
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0

First Broken 
Environmental Variables:
Device: Flame 2.1
BuildID: 20140816141914
Gaia: 5e37ce8c7f0bf6992911d77eb31513db37656aba
Gecko: 9a2152d29d8a
Version: 34.0a1 (2.1) 
Firmware Version: L1TC00011230
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0


Last Working gaia / First Broken gecko - Issue DOES occur
Gaia: 5e37ce8c7f0bf6992911d77eb31513db37656aba
Gecko: 9a2152d29d8a

First Broken gaia / Last Working gekko - Issue does NOT occur
Gaia: 5e37ce8c7f0bf6992911d77eb31513db37656aba
Gecko: 675bab72b8a8

Gecko Pushlog: http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=675bab72b8a8&tochange=9a2152d29d8a

Comment 4

[Joshua Mitchell (Inactive)]

unfortunately, Regression windows on perf issues usually end like this

Comment 5

[Hema Koka [:hema]]

[Blocking Requested - why for this release]: Camera Startup regression (lockscreen case) compared to 2.0. See videos in comment 2.

Diego: I am assigning this to you for investigation and also NI Mike for his input.

Comment 6

[David Flanagan [:djf]]

Did the lockscreen become a separate app in 2.1, or is that only on master? I imagine that that change might have a big impact.  

Since this testing was done on 319mb flames (and the STR include visiting a website first) I would guess that low memory thrashing has something to do with it, and I'm not sure it is fair to count this as a camera regression if it is in fact caused because other apps are using up more memory so the system is thrashing more in 2.2.

No-Jun: do you see a regression if you test on flames that have 512mb of memory?

Comment 7

[No-Jun Park [:njpark]]

with 512MB of memory, the difference between 2.0 and 2.1 was smaller, about less than a second.
I suspect this is due to the memory issue as well- would this fall under a different component in this case?

Comment 8

[Dietrich Ayala (:dietrich)]

Triage reviewed - from the user perspective it's a major regression in performance, which automatically blocks. https://wiki.mozilla.org/B2G/Triage#Blocker_Triage_Guidelines

Comment 9

[David Flanagan [:djf]]

As No-Jun observes in comment #0, this is probably not a camera bug. The regression seems just as likely to be caused by the lockscreen or the homescreen as it is by the camera.

Note that this bug is not about a locked lockscreen where the user has to enter a pin and we launch the camera in secure mode.  It is just the normal lockscreen, and I believe we launch the homescreen and then the camera when the user swipes to the camera.

Diego: if you don't see any obvious changes to the camera that might have caused this, or any changes in the way the lockscreen launches the camera, then consider changing the component on this.

Comment 10

[David Flanagan [:djf]]

Tim,

Have there been any lockscreen changes between 2.0 and 2.1 that could have caused this regression in camera launch time? Do you have any ideas about how we can speed that up?  Is it possible to go directly to from lockscreen to camera without launching or swapping in the homescreen?

Comment 11

[Diego Marcos [:dmarcos]]

I think as well this is not a camera bug. This bug looks like that several running applications are competing for resources that results on everything slowing down. It would be worth to try launching other applications than camera from the lock screen to see if they also take longer to start. Moving this to system.

Comment 12

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

Greg, my memory have faded on what we did between v2.0 and v2.1. What have we done to make the camera launch slow down?

Comment 13

[Greg Weng [:snowmantw][:gweng][:λ]]

I tested this on master 20141005160202, Gaia 2014-10-09 03:44:45 636fdf9a, with 1GB memory (not 319MB yet).

I've found this not a LockScreen issue. Since I use the same path to invoke Camera (MozActivity) without actual unlocking, and I can almost reproduce the slow launching symptom.

What I've seen is if Browser get rid of the 'view' of the page (become white), the activity would be delayed until the view get rendered again. I can reproduce this via entering the card view and while the page become white, leave the card view to the browser again. If you fire the activity at the same time before it renders, you can see the activity would be postponed until the view get rendered again.

Sometime it even get rid of the whole page and it need connect to internet to load the page again (maybe memory issue), in this case if you fire the activity manually just like the first case I listed, the activity would be delayed, too.

Unfortunately to reproduce the 'white' page is not always so successful. Sometime it got re-rendered about only 1 sec and sometimes it took about 3 secs. However, I can say this is not a LockScreen issue according to these tests, since I get the result even I don't lock the screen, but fire the activity directly.

Comment 14

[Cervantes Yu [:cyu] [:cervantes]]

Not sure if this is the root cause, but I saw the main thread of the b2g process spins like no tomorrow. adb logcat shows NetworkGeolocationProvider.js JS error repeatedly as in the attached file. We need to investigate further.

Comment 15

[Cervantes Yu [:cyu] [:cervantes]]

Attachment: NetworkGeolocationProvider.js error

Comment 16

[:gerard-majax]

I'll try to profile and see what happens.

Comment 17

[:gerard-majax]

Profiled on a master JB Flame (I don't have a KK right now): http://people.mozilla.org/~bgirard/cleopatra/#report=06ef2fb1491fbe23692960f739120989dbe6184b

Comment 18

[:gerard-majax]

Doh, sorry, I missed the "from lockscreen" part.

Comment 19

[:gerard-majax]

I've noticed a slight bump in pid when trying to properly track this from lockscreen. And Find my device appears when I do launch the camera from the lockscreen. Maybe it's related ...

Comment 20

[:gerard-majax]

And lockscreen calling findmydevice landed ... on august 16th, as per bug 1027749 comment 15.

Comment 21

[Guilherme Gonçalves [:ggp]]

If this is being caused by FMD, bug 1062558 will greatly help by not launching the background app unless FMD is enabled.

Comment 22

[Mark Goodwin [:mgoodwin]]

Assuming FMD is an issue, we can also improve this by not launching FMD if the lockscreen goes to camera.  It may be possible to do this with a similar approach to that used for the sim lock.

Comment 23

[:gerard-majax]

I've got some local patch to fix this and measure the time. I'm taking the timestamp when findmydevice IAC launcher gets the event and then the timestamp at the end of the initiliaze function of camera app.

Comment 24

[:gerard-majax]

Attachment: Diff to measure launch time

Please note that one should comment one of the two event listeners, depending on what we want to measure.

Comment 25

[:gerard-majax]

Attachment: camera-lockscreen.png

Figures are given in ms.

Left part shows the current situation:
> mean	stddev
> 2568,3	113,8479004833

Right part shows after not launching FMD when we launch camera app:
> mean	stddev
>1340,4	27,7776888887

Comment 26

[:gerard-majax]

Attachment: Gaia PR

This will disable launching FMD when the Camera app is being launched from lockscreen.

Comment 27

[Gregor Wagner [:gwagner]]

Hema, can you make sure this gets proper testing so it doesn't regress any more?

Comment 28

[Jared Hirsch [:jhirsch] (PTO, back 5/28) (he/him) (Needinfo please)]

This is related to bug 1062558.

The 1062558 patch prevents FMD from launching when it's disabled. When it's enabled, we still attach all the same listeners, except we listen for lockscreen-appclosed instead of lockscreen-appclosing, per Alive's advice. I don't know if that will avoid the slowdown when launching Camera. The best solution is probably to use both patches.

Comment 29

[Kevin Grandon :kgrandon]

(In reply to Jared Hirsch [:_6a68] [@6a68] from comment #28)
> This is related to bug 1062558.
> 
> The 1062558 patch prevents FMD from launching when it's disabled. When it's
> enabled, we still attach all the same listeners, except we listen for
> lockscreen-appclosed instead of lockscreen-appclosing, per Alive's advice. I
> don't know if that will avoid the slowdown when launching Camera. The best
> solution is probably to use both patches.

Yeah, I think we should land both patches, especially this one because it's blocking 2.1.

Comment 30

[Kevin Grandon :kgrandon]

Comment on attachment 8503236 [details] [review]
Gaia PR

Looks good and works nicely. Thanks!

Comment 31

[:gerard-majax]

Green try: https://treeherder.mozilla.org/ui/#/jobs?repo=gaia-try&revision=bdc4cbed79f0

Comment 32

[:gerard-majax]

https://github.com/mozilla-b2g/gaia/commit/89db9df1f1409841a6682c8447cc19af0769cc90

Comment 33

[:gerard-majax]

Comment on attachment 8503236 [details] [review]
Gaia PR

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #): 1027749
[User impact] if declined: longer launch time for camera from lockscreen
[Testing completed]: on device, several runs as documented in comment 25
[Risk to taking this patch] (and alternatives if risky): low
[String changes made]: none

Comment 34

[bhavana bajaj [:bajaj]]

Comment on attachment 8503236 [details] [review]
Gaia PR

Approving this for 2.1 lets also get QA verification that the performance is imprvoved or back to where it was once this lands on 2.1

Comment 35

[Ryan VanderMeulen [:RyanVM]]

v2.1: https://github.com/mozilla-b2g/gaia/commit/137bb1f7943a2f47292d82091b1d2982218071ff

Comment 36

[Tony Chung [:tchung]]

(In reply to Jared Hirsch [:_6a68] [NEEDINFO pls] from comment #28)
> This is related to bug 1062558.
> 
> The 1062558 patch prevents FMD from launching when it's disabled. When it's
> enabled, we still attach all the same listeners, except we listen for
> lockscreen-appclosed instead of lockscreen-appclosing, per Alive's advice. I
> don't know if that will avoid the slowdown when launching Camera. The best
> solution is probably to use both patches.

Qanalysts, To verify, please have b2g-info or firewatch running to check if Find my device process is not running on launch.  Please also retry the side by side tests like comment 2 to see if there's a significant slowdown.  thanks

Comment 37

[Chris Kreinbring [:CKreinbring]]

Using the b2g-info command, we found that the Find My Device process does run on launch on today's Flame 2.2 and Flame 2.1 nightly builds with full flash.  The results of five restarts are below:

Flame 2.2
           NAME  PID PPID CPU(s) NICE  USS  PSS  RSS SWAP VSIZE OOM_ADJ USER    
 Find My Device 1166  369    1.0   18  6.9 10.2 21.2  1.3  81.1      10 u0_a1166
 Find My Device 1166  303    1.0   18  6.9 10.2 21.2  1.4  82.1      10 u0_a1166
 Find My Device 1156  323    1.0   18  6.4  9.8 20.7  1.3  81.1      10 u0_a1156
 Find My Device 1171  363    1.0   18  6.8 10.2 21.2  1.3  82.1      10 u0_a1171
 Find My Device 1193  376    1.0   18  6.4  9.8 20.7  1.3  82.1      10 u0_a1193

Flame 2.1
           NAME  PID PPID CPU(s) NICE  USS  PSS  RSS SWAP VSIZE OOM_ADJ USER    
 Find My Device 1177  316    0.9   18  6.0  9.3 20.0  0.7  61.9      10 u0_a1177
 Find My Device 1170  394    0.8   18  6.0  9.2 19.4  1.3  62.8      10 u0_a1170
 Find My Device 1148  319    0.9   18  5.9  9.3 19.9  0.7  62.9      10 u0_a1148
 Find My Device 1149  395    0.9   18  5.9  9.1 19.3  1.4  62.9      10 u0_a1149
 Find My Device 1174  369    0.9   18  6.0  9.3 20.0  0.7  62.9      10 u0_a1174

The side-by-side tests show that the Flame 2.2 is a few seconds slower than 2.0, and the Flame 2.1 is about a second slower than 2.0

2.0 and 2.1: http://youtu.be/SdYxmsBDOCg
2.0 and 2.2: http://youtu.be/401G-Ou_adI

Flame 2.2
BuildID: 20141015040201
Gaia: 5f1f0960ae9d22acf2a324ad37a48174d6df87f6
Gecko: 62f0b771583c
Gonk: 52c909e821d107d414f851e267dedcd7aae2cebf
Platform Version: 36.0a1
Firmware Version: V180
User Agent: Mozilla/5.0 (Mobile; rv:36.0) Gecko/36.0 Firefox/36.0

Flame 2.1
BuildID: 20141015001201
Gaia: 379ea4c9dd6d3f8ca2f79ce59c15f6afe6e557c3
Gecko: 4853208cb48a
Gonk: 52c909e821d107d414f851e267dedcd7aae2cebf
Platform Version: 34.0
Firmware Version: V180
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0

Comment 38

[:gerard-majax]

So, what should we deduce from comment 37 ?

Because when I check on my Flame, I don't see any line like:
> 10-16 11:36:55.877  9069  9069 I GeckoDump: [findmydevice] got wake up request
> 10-16 11:36:55.877  9069  9069 I GeckoDump: [findmydevice] unlocked

Please make sure you have enabled Gaia debug traces in developper menu, and unlock directly to Camera. If you see those lines, there's a problem.

Please also provide more reliable informations on the timing you see. I documented startup time and how I did the measure in comment 24 and comment 25. Given the values, "a few seconds" is completely irrelevant at best. My measurements shows we cut the time to get to the "initialized" state in Camera in half: from 2.6s to 1.3s.

Comment 39

[:gerard-majax]

Following comment 37, did you made sure there was no pre-existing "Find my device" process before listing them ?

By default, FMD process could get started on boot. So having a running process may be an expected outcome during your test unless you explicitely killed it before.

Comment 40

[Peter Bylenga [:PBylenga]]

Adding QAWanted to assist in Comment 38 and Comment 39.  You will need to apply the patch to expose additional logging while performing the test.

Comment 41

[Jayme Mercado [:JMercado] (Inactive 3/4/2016)]

I attempted to manually make the patch attached above but ran into a snag in that window.addEventListener('lockscreen-request-unlock', function(event) is already defined in findmydevice_launcher.js as the following:

window.addEventListener('lockscreen-request-unlock', function(event) {
  if (event.detail && event.detail.activity &&
      'record' === event.detail.activity.name) {
    // Let's make sure we won't start FMD when user triggers Camera from
    // the lockscreen.
    return;
  }

Which sounds like it might make this testing invalid.  The questions I have are:
1) Given the above is the testing still valid?
2) Is there a way to get the requested logging that does not have me blindly (and possibly incorrectly) changing the .js files?
3) If yes to question 1 and no to question 2, is the attached diff still the correct changes to make and if not correct can it be updated to make it so?

Thank you

Comment 42

[:gerard-majax]

(In reply to Jayme Mercado [:JMercado] from comment #41)
> I attempted to manually make the patch attached above but ran into a snag in
> that window.addEventListener('lockscreen-request-unlock', function(event) is
> already defined in findmydevice_launcher.js as the following:

Yes, since ... my code landed to fix the issue ?

> 
> window.addEventListener('lockscreen-request-unlock', function(event) {
>   if (event.detail && event.detail.activity &&
>       'record' === event.detail.activity.name) {
>     // Let's make sure we won't start FMD when user triggers Camera from
>     // the lockscreen.
>     return;
>   }

Just record the start date just before the |return| statement.

> 
> Which sounds like it might make this testing invalid.  The questions I have
> are:
> 1) Given the above is the testing still valid?
> 2) Is there a way to get the requested logging that does not have me blindly
> (and possibly incorrectly) changing the .js files?
> 3) If yes to question 1 and no to question 2, is the attached diff still the
> correct changes to make and if not correct can it be updated to make it so?

I provided steps and figures to document the improvements. You never addressed my comment 38 and comment 39 to make sure that you were properly testing.

Comment 43

[Johan Lorenzo [:jlorenzo]]

No-Jun, is the performance back to a reasonable value since gerard-majax's fix? If so, can we mark this bug as verified? Thanks!

Comment 44

[No-Jun Park [:njpark]]

(In reply to Johan Lorenzo [:jlorenzo] (QA) from comment #43)
> No-Jun, is the performance back to a reasonable value since gerard-majax's
> fix? If so, can we mark this bug as verified? Thanks!

Will do, yes the performance has improved significantly after the fix.

Comment 45

[sarsenyev]

Verified the issue is fixed on 2.2 and 2.1 Flame,
Loading time has improved significantly after the fix

Device: Flame 2.2 Master KK
BuildID: 20141112040208
Gaia: 5ae28ff11b982e2bd7d1aa097cda131536952bdc
Gecko: 688f821edcd4
Gonk: 
Version: 36.0a1 (2.2 Master)
Firmware: V188-1
User Agent: Mozilla/5.0 (Mobile; rv:36.0) Gecko/36.0 Firefox/36.0

Device: Flame 2.1 KK
BuildID: 20141112001201
Gaia: 4c159e75a1568afbbf0c83c1235ec56facfbe87d
Gecko: b9849b3c6aaa
Gonk: 
Version: 34.0 (2.1)
Firmware: V188-1
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0