Closed Bug 1067865 Opened 6 years ago Closed 6 years ago

[camera] Startup performance regressed (datazilla)

Categories

(Firefox OS Graveyard :: Gaia::Camera, defect)

x86
macOS
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: wilsonpage, Assigned: wilsonpage)

Details

(Keywords: perf)

A commit [1] which changed the way gaia-icons loaded caused a ~200-300ms regression on the critical path.

[1] https://github.com/mozilla-b2g/gaia/commit/db35856eb07b21f952445ed1f2cc5a450e23ac38#diff-b8bbcd834d411eb51460810dafde25df
I've tried to reproduce the issue locally but am getting very different numbers. With my device locked to 319mb memory I am getting Camera startup numbers between 1400-1500ms, which is ~400-500ms faster than what Datazilla is reporting.

dmarcos, justindarc: Can you tell us the critical-path time you get for Camera startup at current master with a 319mb restricted Flame. You can learn how to alter the memory of your Flame here [1].

eli: Can you give us any advice here? Why might we be experiencing such different numbers on our own devices?

[1] https://developer.mozilla.org/en-US/Firefox_OS/Developer_phone_guide/Flame#RAM_adjustment
Flags: needinfo?(jdarcangelo)
Flags: needinfo?(eperelman)
Flags: needinfo?(dmarcos)
Summary: [camera] Startup performance regressed → [camera] Startup performance regressed (datazilla)
Did you `make reference-workload-light` before running your local tests? That is I think one of the only differences between the setup on Jenkins and running local tests.
Flags: needinfo?(eperelman)
Yeah, the reference workload is the main one. As Eli said, the DZ tests run with workload-light.

The mean is going to be misleading on these, because the first result of each run of 30 is consistently slower. This is because of a problem in our testing methodology in general, I think (the first run is doing something the rest aren't, like initializing app files or priming the permissions db query, or something like that) and can be fixed at a harness level. I've been working on confirming this and getting the right bugs filed.

In the meantime, switching to median more accurately reflects what would have been the mean of the scenario reflected by the other 29 results, "cold launch after process kill". But that doesn't account for anywhere near 400ms, I only see a drop of maybe 50ms or so from going to median.

Grasping at straws, but does the initialization time of the preview stream depend at all on environmental factors like ambient light, whether it can focus the image, etc? Any chance that the phones submitting to DZ are running a different base build or Gonk?
(In reply to Geo Mealer [:geo] from comment #4)
> Grasping at straws, but does the initialization time of the preview stream
> depend at all on environmental factors like ambient light, whether it can
> focus the image, etc?

No. For initializing the preview stream, these environmental factors wouldn't affect startup time. The only metric that they could possibly affect would be measuring the time it takes to take a picture (from tapping capture button until picture is saved). But for simply loading the preview stream, that shouldn't matter.
I realized I should have put this comment as well as sending it out on email:

I compared the performance between 2.1 and master on camera app, because on datazilla it seemed to regressed by nearly 500ms.  

With Wilson’s help, I checked the Camera app completion time in logcat between the two builds. 

I measured the time after rebooting twice, to avoid the issue of first time run having excess processes in memory (see https://bugzilla.mozilla.org/show_bug.cgi?id=1068826 )
In 2.1:
E/GeckoConsole( 1461): Content JS LOG at app://camera.gaiamobile.org/js/main.js:3 in n.prototype.logPerf: critical-path: 1307ms
E/GeckoConsole( 1461): Content JS LOG at app://camera.gaiamobile.org/js/main.js:3 in n.prototype.logPerf: app-fully-loaded: 1975ms
E/GeckoConsole( 1540): Content JS LOG at app://camera.gaiamobile.org/js/main.js:3 in n.prototype.logPerf: critical-path: 1266ms
E/GeckoConsole( 1540): Content JS LOG at app://camera.gaiamobile.org/js/main.js:3 in n.prototype.logPerf: app-fully-loaded: 1969ms

In master:
E/Camera  ( 2444): Content JS LOG at app://camera.gaiamobile.org/js/main.js:7767 in App.prototype.logPerf: critical-path: 1360ms
E/Camera  ( 2444): Content JS LOG at app://camera.gaiamobile.org/js/main.js:7769 in App.prototype.logPerf: app-fully-loaded: 2190ms
E/Camera  ( 2520): Content JS LOG at app://camera.gaiamobile.org/js/main.js:7767 in App.prototype.logPerf: critical-path: 1285ms
E/Camera  ( 2520): Content JS LOG at app://camera.gaiamobile.org/js/main.js:7769 in App.prototype.logPerf: app-fully-loaded: 2115ms
E/Camera  ( 2595): Content JS LOG at app://camera.gaiamobile.org/js/main.js:7767 in App.prototype.logPerf: critical-path: 1284ms
E/Camera  ( 2595): Content JS LOG at app://camera.gaiamobile.org/js/main.js:7769 in App.prototype.logPerf: app-fully-loaded: 2168ms

Maybe the app-fully-loaded value have increased a bit, but it does not seem that there was a huge regression in master as datazilla says, *once* the initial run was discarded.  (Bug 1068826 is being worked on at the moment)
actually, as of September 24th, I see some delays in the log- looks like it's about 500ms slower for app-fully-loaded value.  Worthwhile to check whether this is a temporary spike or a real issue.

In Master:
I/Camera  ( 1451): Content JS LOG: critical-path: 1417ms 
I/Camera  ( 1451):     at s.prototype.logPerf (app://camera.gaiamobile.org/js/main.js:3:15310)
I/Camera  ( 1451): Content JS LOG: app-fully-loaded: 2654ms 
I/Camera  ( 1451):     at s.prototype.logPerf (app://camera.gaiamobile.org/js/main.js:3:15384)

I/Camera  ( 1567): Content JS LOG: critical-path: 1495ms 
I/Camera  ( 1567):     at s.prototype.logPerf (app://camera.gaiamobile.org/js/main.js:3:15310)
I/Camera  ( 1567): Content JS LOG: app-fully-loaded: 2619ms 
I/Camera  ( 1567):     at s.prototype.logPerf (app://camera.gaiamobile.org/js/main.js:3:15384)
While the values for app-fully-loaded are interesting, the startup regression numbers should be based on the times from moz-app-visually-complete which is what is being reported to Datazilla. Even though the critical path time is captured around the same moment as moz-app-visually-complete, the numbers are not comparable to the ones reported in Datazilla. Feel free to ni? if you need further clarification.
Startup time seems to have stabilised now.
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Flags: needinfo?(jdarcangelo)
Flags: needinfo?(dmarcos)
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.