821841 - Camera - platform start-up time

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: General, defect)

Description

[Mike Habicher [:mikeh] (high bugzilla latency)]

I don't believe there is much we can do to improve start-up time in the platform, but creating this bug just in case.

From bug 817051, comment 8:

  +0 ms : camera control object is created by the DOM
 +10 ms : camera initialization starts opening the hardware
+620 ms : hardware is open[1]
 +34 ms : hardware is configured
  +5 ms : camera control object is returned to JS, JS calls getPreviewStream()
 +55 ms : preview stream is returned, attached to <video> element, StartPreview() is called
+130 ms : hardware finishes starting the preview[2]
 +64 ms : the first preview frame is returned by the hardware[3]
-------
 918 ms

The huge items, [1] and [2], take place almost entirely within the camera driver ([3] does as well), so there isn't a lot of room to tweak these on our end.

Comment 1

[Mike Habicher [:mikeh] (high bugzilla latency)]

Attachment: WIP - add a profiler to examine camera startup in the platform

This patch adds a profiler to instrument start up:

I/Gecko   ( 1098): +--- Profile report for 'Camera.Startup':
I/Gecko   ( 1098): |    0. +      0 us, mozilla::CameraControlImpl::CameraControlImpl(uint32_t, nsIThread*, uint64_t):32
I/Gecko   ( 1098): |    1. +  10620 us, nsresult mozilla::nsGonkCameraControl::Init():212
I/Gecko   ( 1098): |    2. + 717224 us, nsresult mozilla::nsGonkCameraControl::Init():214
I/Gecko   ( 1098): |    3. +  35126 us, nsresult mozilla::nsGonkCameraControl::Init():259
I/Gecko   ( 1098): |    4. +   4242 us, virtual nsresult mozilla::CameraControlImpl::GetPreviewStream(mozilla::dom::CameraSize, nsICameraPreviewStreamCallback*, nsICameraErrorCallback*):315
I/Gecko   ( 1098): |    5. +  56122 us, virtual nsresult mozilla::CameraControlImpl::StartPreview(mozilla::DOMCameraPreview*):354
I/Gecko   ( 1098): |    6. + 150818 us, virtual nsresult mozilla::nsGonkCameraControl::StartPreviewImpl(mozilla::StartPreviewTask*):627
I/Gecko   ( 1098): | dtor. +  64544 us
I/Gecko   ( 1098): +--- End of report for 'Camera.Startup'

0. the construction of the profiler (during the CameraControl constructor, which runs on the Main Thread)
1. the start of CameraControl initialization on the Camera Thread
2. after calling GonkCameraHardware::GetHandle(), which is where the hardware is opened/initialized
3. end of the remaining camera initialization
4. entry into the C++ handler for nsIDOMCameraControl::getPreviewStream()
5. entry into StartPreview(), which occurs after the DOMCameraPreview MediaStream is connected to the viewfinder <video> tag
6. after the call to GonkCameraHardware::StartPreview() returns

Profiler object is destroyed when the first frame is returned from the camera hardware.

Entry [2] can be further broken down to:

I/Gecko   ( 1098): +--- Profile report for 'GonkCameraHardware::Init()':
I/Gecko   ( 1098): |    0. +      0 us, void mozilla::GonkCameraHardware::Init():180
I/Gecko   ( 1098): |    1. +    244 us, void mozilla::GonkCameraHardware::Init():186
I/Gecko   ( 1098): |    2. +      0 us, void mozilla::GonkCameraHardware::Init():192
I/Gecko   ( 1098): |    3. + 707001 us, void mozilla::GonkCameraHardware::Init():199
I/Gecko   ( 1098): |    4. +   3693 us, void mozilla::GonkCameraHardware::Init():209
I/Gecko   ( 1098): |    5. +     30 us, void mozilla::GonkCameraHardware::Init():222
I/Gecko   ( 1098): |    6. +    946 us, void mozilla::GonkCameraHardware::Init():229
I/Gecko   ( 1098): | dtor. +      0 us
I/Gecko   ( 1098): +--- End of report for 'GonkCameraHardware::Init()'

0. is entry into this function
1. after hw_get_module()
2. after construction of new CameraHardwareInterface object
3. after initialize()
4. after get_camera_info()
5. after __system_property_get()
6. after setCallbacks()

Thus most of the camera start-up time in the platform is due to the initialize() call.

Comment 3

[Rafael Rebolleda]

Adding UX-P2 for the UX team to track this bug. Start time in Camera is one of the biggest issues with it now.

Comment 4

[Rafael Rebolleda]

Perhaps related to bug 816356

Comment 5

[Mike Habicher [:mikeh] (high bugzilla latency)]

Pasting in gsvelto's info from bug 833114 comment 2:

I've looked into the issue by applying highly advanced profiling methods (*cough* clock_gettime() *cough*) and from what I can see most of the time is sunk in getting the hardware device handle to the camera and pushing the parameters:

https://mxr.mozilla.org/mozilla-central/source/dom/camera/GonkCameraControl.cpp#226

I've timed the Otoro, the Unagi and another device who shalt not be named and the results vary quite a lot between them:

* Otoro

GonkCameraHardware::GetHandle()            ~250ms
nsGonkCameraControl::PushParametersImpl() ~1100ms

* Unagi

GonkCameraHardware::GetHandle()            ~800ms
nsGonkCameraControl::PushParametersImpl()   ~50ms

* Device who shalt not be named

GonkCameraHardware::GetHandle()            ~500ms
nsGonkCameraControl::PushParametersImpl()   ~50ms

The numbers vary quite a bit from time to time, sometimes jumping up by as much as 2-300ms so I've written down those that seemed to come up more consistently, they're not averages. I'll attach a patch with the code I've used for testing this so that you can reproduce my measurements.

Without knowing the code better I would say that there's no way around this unless we can start the process of setting up the camera in parallel with the application launch in the hope that overlap saves us some time.

Comment 6

[Mike Habicher [:mikeh] (high bugzilla latency)]

Attachment: WIP - profiler patch (just define the profiler, no profiling statements added)

Like attachment 692445 [details] [diff] [review], but doesn't include any of the tags--just the profiler.

Comment 7

[David Scravaglieri [:scravag]]

Michael, could you help to find someone to help Mike at a driver level ?

Comment 8

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

Talked with mikeh out of band and he'll set up other bugs for this

Comment 9

[Dietrich Ayala (:dietrich)]

Mike, any update here? This is the only bug currently blocking camera startup perf improvements required for build acceptance for downstream consumers.

Comment 10

[Mike Habicher [:mikeh] (high bugzilla latency)]

Dietrich, I went through the platform start-up time with Inder, and unfortunately we don't believe there are any gains to be had.  Performance at the platform level is comparable to Android.

Comment 11

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

(FWIW, our perf folks now seem content with the current camera start time for v1.0.1 once bug 834620 lands)

Comment 12

[Mike Habicher [:mikeh] (high bugzilla latency)]

I think any further improvements will have to involve the device manufacturer.  It would be nice to knock down that 700ms hardware-initialization process.

Comment 13

[Dietrich Ayala (:dietrich)]

Ok, thanks all. Can this be closed then?

Comment 14

[Mike Habicher [:mikeh] (high bugzilla latency)]

I think so.  If we make any major breakthroughs, we'll create a new bug.

Comment 15

[Mike Habicher [:mikeh] (high bugzilla latency)]

Attachment: WIP - add a profiler to examine camera startup in the platform, m-c version

Updated to apply over m-c:ca8fd217b836