If you think a bug might affect users in the 57 release, please set the correct tracking and status flags for Release Management.

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

VERIFIED FIXED in Firefox OS v2.1

Status

Firefox OS
FindMyDevice
VERIFIED FIXED
3 years ago
3 years ago

People

(Reporter: njpark, Assigned: gerard)

Tracking

({regression})

unspecified
2.1 S6 (10oct)
ARM
Linux
regression

Firefox Tracking Flags

(blocking-b2g:2.1+, b2g-v2.1 verified, b2g-v2.2 verified)

Details

(Whiteboard: [systemsfe])

Attachments

(4 attachments)

(Reporter)

Description

3 years ago
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
(Reporter)

Comment 1

3 years ago
In the video, left is 2.0 device, and right is 2.2.  Both has 319MB of ram, on v180 KK base image.
blocking-b2g: --- → 2.2?
status-b2g-v2.2: --- → affected
Keywords: regression
Keywords: regressionwindow-wanted
(Reporter)

Comment 2

3 years ago
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.
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
QA Whiteboard: [QAnalyst-Triage?]
Flags: needinfo?(jmitchell)
Keywords: regressionwindow-wanted
unfortunately, Regression windows on perf issues usually end like this
QA Whiteboard: [QAnalyst-Triage?] → [QAnalyst-Triage+]
Flags: needinfo?(jmitchell)

Comment 5

3 years ago
[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.
Assignee: nobody → dmarcos
blocking-b2g: 2.2? → 2.1?
Flags: needinfo?(mhabicher)
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?
(Reporter)

Comment 7

3 years ago
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?
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
blocking-b2g: 2.1? → 2.1+
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.
Flags: needinfo?(dmarcos)
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?
Flags: needinfo?(timdream)
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.
Component: Gaia::Camera → Gaia::System
Flags: needinfo?(dmarcos)
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?
Flags: needinfo?(timdream) → needinfo?(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.
Flags: needinfo?(gweng)
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.
Created attachment 8502318 [details]
NetworkGeolocationProvider.js error
Flags: needinfo?(mhabicher)
Assignee: dmarcos → nobody
(Assignee)

Comment 16

3 years ago
I'll try to profile and see what happens.
Assignee: nobody → lissyx+mozillians
(Assignee)

Comment 17

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

Comment 18

3 years ago
Doh, sorry, I missed the "from lockscreen" part.
(Assignee)

Comment 19

3 years ago
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 ...
(Assignee)

Comment 20

3 years ago
And lockscreen calling findmydevice landed ... on august 16th, as per bug 1027749 comment 15.
Depends on: 1027749
Flags: needinfo?(mgoodwin)
If this is being caused by FMD, bug 1062558 will greatly help by not launching the background app unless FMD is enabled.
Flags: needinfo?(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.
(Assignee)

Comment 23

3 years ago
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.
(Assignee)

Comment 24

3 years ago
Created attachment 8503226 [details]
Diff to measure launch time

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

Comment 25

3 years ago
Created attachment 8503229 [details]
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
(Assignee)

Comment 26

3 years ago
Created attachment 8503236 [details] [review]
Gaia PR

This will disable launching FMD when the Camera app is being launched from lockscreen.
Attachment #8503236 - Flags: review?(mgoodwin)
Whiteboard: [systemsfe]
Component: Gaia::System → FindMyDevice
Summary: [Flame][KK] The time to start up camera from lockscreen is regressed compared to 2.0 → [Flame][KK] The time to start up camera from lockscreen is regressed compared to 2.0 because of FMD
Hema, can you make sure this gets proper testing so it doesn't regress any more?
Flags: needinfo?(hkoka)
(Assignee)

Updated

3 years ago
Attachment #8503236 - Flags: review?(mgoodwin) → review?(kgrandon)
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.
(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 on attachment 8503236 [details] [review]
Gaia PR

Looks good and works nicely. Thanks!
Attachment #8503236 - Flags: review?(kgrandon) → review+
(Assignee)

Comment 31

3 years ago
Green try: https://treeherder.mozilla.org/ui/#/jobs?repo=gaia-try&revision=bdc4cbed79f0
(Assignee)

Comment 32

3 years ago
https://github.com/mozilla-b2g/gaia/commit/89db9df1f1409841a6682c8447cc19af0769cc90
Status: NEW → RESOLVED
Last Resolved: 3 years ago
Flags: needinfo?(hkoka)
Resolution: --- → FIXED
(Assignee)

Comment 33

3 years ago
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
Attachment #8503236 - Flags: approval-gaia-v2.1?
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
Attachment #8503236 - Flags: approval-gaia-v2.1? → approval-gaia-v2.1+

Updated

3 years ago
Keywords: verifyme
v2.1: https://github.com/mozilla-b2g/gaia/commit/137bb1f7943a2f47292d82091b1d2982218071ff
status-b2g-v2.1: --- → fixed
status-b2g-v2.2: affected → fixed
Target Milestone: --- → 2.1 S6 (10oct)
(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
Flags: needinfo?(ktucker)
QA Whiteboard: [QAnalyst-Triage+] → [QAnalyst-Triage-]
Flags: needinfo?(ktucker) → needinfo?(pbylenga)
Flags: needinfo?(pbylenga) → needinfo?(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
QA Whiteboard: [QAnalyst-Triage-] → [QAnalyst-Triage?]
Flags: needinfo?(ckreinbring) → needinfo?(pbylenga)
(Assignee)

Comment 38

3 years ago
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.
(Assignee)

Comment 39

3 years ago
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.
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.
Flags: needinfo?(pbylenga)
Keywords: qawanted
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
QA Whiteboard: [QAnalyst-Triage?]
Flags: needinfo?(pbylenga)
Flags: needinfo?(lissyx+mozillians)
Keywords: qawanted
(Assignee)

Comment 42

3 years ago
(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.
Flags: needinfo?(lissyx+mozillians)
Flags: needinfo?(pbylenga)
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!
Flags: needinfo?(npark)
(Reporter)

Comment 44

3 years ago
(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.
Status: RESOLVED → VERIFIED
Flags: needinfo?(npark)

Comment 45

3 years ago
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
QA Whiteboard: [QAnalyst-Triage?]
status-b2g-v2.1: fixed → verified
status-b2g-v2.2: fixed → verified
Flags: needinfo?(ktucker)
Keywords: verifyme
QA Whiteboard: [QAnalyst-Triage?] → [QAnalyst-Triage+]
Flags: needinfo?(ktucker)
You need to log in before you can comment on or make changes to this bug.