817051 - (Camera-Startup) [meta][Gaia::Camera] Long initial startup time for Camera app

Status: RESOLVED FIXED

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

Description

[Peter La]

What makes it feel slow/broken?
It takes too long to startup the Camera app after a reset.  Currently ~5 seconds, or more.  David Clarke to provide more accurate, recent numbers.

Did it prevent you from doing what you wanted? Why?

How does this make you feel?

[ ]  :)  I feel happy about it
[ ]  :|  Meh
[X]  :(  I'm upset
[ ] >:O  I'm angry

Device: Original numbers from Unagi, Nov. 22 nightly.  David Clarke to get Otoro numbers.

Details: (technical factors, FPS, app startup time, ms elapsed, etc)

Bonus: can you attach a video of the problem?
See metabug 814981

Comment 1

[Peter La]

Additional info:

Comparable -
Android ICS 4.0.4 on Otoro - 3.5 seconds cold launch for Camera.

David Clarke to provide our current numbers for B2G on Otoro.

Comment 2

[Joe Cheng [:jcheng] (please needinfo)]

BB+, P3 - performance on frequently used Camera app

Comment 3

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

This bug seems like a meta bug and we don't block on meta bug. Someone need to investigate the reasons why it is slow and open blocking bugs that blocks this one.

Also the exact timing method should be described so the people that are going to work on it will be able to compare.

Renominating and triagers please explain why we block on a meta bug.

Comment 4

[David Scravaglieri [:scravag]]

Hey Gabriele, could you investigate to see what is slow please ?

Comment 5

[Gabriele Svelto [:gsvelto] (PTO)]

This is a profile of the camera app starting up:

http://people.mozilla.com/~bgirard/cleopatra/#report=51627df6c9f34973b48d02d8eab071eafe7e24dd

The application itself seems to be quite well behaved, with most of the code starting up in 2.6s but there are a couple of problems that stretch the total startup at up to 5s.

The first problem is that the app does not launch withing the pre-allocated application. This is the same problem I noticed in the Video app, fixing it will easily reduce the startup time by up to 1s.

The second problem seems a platform issue on the other hand. When the navigator.mozCameras.getCamera() gets called the application seems to wait for over 1s before the gotCamera() function gets called. During this period no activity is present, it would be interesting to see what's going on on the platform side.

There are other aspects that show up on the profile even though they are not major: code in l10n.js first of all takes ~240ms to execute. It's not much but since the camera application is almost completely devoid of text it's a bit surprising.

Parsing videocontrols.xml also takes ~200ms. Again it's not major as that file is quite large but it might be worth investigating if it can be reduced once the major problems have been addressed.

Comment 6

[Gabriele Svelto [:gsvelto] (PTO)]

This application cannot use the prelaunched process like most of the others because it needs special permissions to run, see bug 786631. I'm not putting it as a dependency because this bug is a blocker and 786631 is not.

Comment 7

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

This is bb- while 817051 is bb+?  :)

Comment 8

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

(In reply to Mike Habicher [:mikeh] from comment #7)
> This is bb- while 817051 is bb+?  :)

(Wow, I so meant to put that comment in bug 819263.)

I've done some profiling of the camera startup, and here's a typical sequence of events:

  +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

Unfortunately, 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 9

[David Flanagan [:djf]]

Displaying a spinner of some sort while the device driver is busy would be nice so we're not displaying a back screen.

Comment 10

[Alex Keybl [:akeybl]]

This performance bug represents a non-trivial amount of work. Marking as a P1 issue to frontload risk.

Comment 11

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

Can we block on specific bugs and not on [This APP is slow] fuzzy bug? This make it hard to really understand what work is ungoing and to split the work between people and between teams when it comes to front-end versus backend.

blocking-basecamp? but I belive this is a meta bug and should be bb-.

Comment 12

[David Scravaglieri [:scravag]]

Considering this as meta

Comment 13

[Josh Carpenter [:jcarpenter]]

(In reply to David Flanagan [:djf] from comment #9)
> Displaying a spinner of some sort while the device driver is busy would be
> nice so we're not displaying a back screen.

Agreed. Patryk, is this something you can make a recommendation on? Sounds like we need a standard BB low-fps spinner?

Comment 14

[Chris Lee [:clee]]

Vivien, before unplus this bug, can we file specific bugs off this one so we don't lose track of it?  I believe that Gabriele/Mike are doing some good profiling work here to understand the issue which is needed to determine the specific areas to fix.  

We must fix these app launch latencies so however we want to track them I don't care, but let's not drop this because this is considered 'meta'. 

David S, can you help ensure we have specific bugs that address this core issue if we don't want to track the work here?  Thanks.

Comment 15

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

Further platform investigation in bug 821841.

Comment 16

[Josh Carpenter [:jcarpenter]]

(In reply to Chris Lee [:clee] from comment #14)
> Vivien, before unplus this bug, can we file specific bugs off this one so we
> don't lose track of it?  I believe that Gabriele/Mike are doing some good
> profiling work here to understand the issue which is needed to determine the
> specific areas to fix.  
> 
> We must fix these app launch latencies so however we want to track them I
> don't care, but let's not drop this because this is considered 'meta'. 
> 
> David S, can you help ensure we have specific bugs that address this core
> issue if we don't want to track the work here?  Thanks.

Guys, we now have 4 bugs depedencies attached to this one, but 3 of them are non-blocking. Am I correct in assuming, based on the random nature of the depends bugs, that the solution to this issue is fairly amorphous, involving fixes to multiple bugs that are not directly tied to Camera? What's your opinion on the best way to resolve this? Should we work to get those 3 bugs BB+?

Comment 17

[Gabriele Svelto [:gsvelto] (PTO)]

(In reply to Josh Carpenter [:jcarpenter] from comment #16)
> Guys, we now have 4 bugs depedencies attached to this one, but 3 of them are
> non-blocking. Am I correct in assuming, based on the random nature of the
> depends bugs, that the solution to this issue is fairly amorphous, involving
> fixes to multiple bugs that are not directly tied to Camera? What's your
> opinion on the best way to resolve this? Should we work to get those 3 bugs
> BB+?

The thing is that bugs 819000, 820196, and 821691 will shorten the start-up time of any gaia app and thus the camera app too. Maybe it would be better to move these bugs into a meta-bug for generic gaia start-up improvements and make this bug block only on camera-specific ones.

Comment 18

[Gabriele Svelto [:gsvelto] (PTO)]

While profiling the application again I've noticed a peculiar thing, this is the profile with only the code from videocontrols.xml highlighted:

http://people.mozilla.com/~bgirard/cleopatra/#report=40d5408a8d23b67bb82148ed4178742b34b00dcf&search=videocontrols.xml

If you look at the two first blocks on the left you'll notice that the videocontrols.xml file is parsed and initialized twice (you can see the .init() call from line 1338 twice). The first time it's loaded and initialized as part of the regular loading process, the second time it seems to happen as part of a layout operation.

Each iteration takes ~180ms so if we can get rid of the second one that could be a nice win. I'll try to confirm this finding and open another bug on the topic.

Comment 19

[Andrew Overholt [:overholt]]

This is a meta bug and we only block on bugs that are actionable.

Comment 20

[David Scravaglieri [:scravag]]

Dale, could you investigate on this issue and give us feedback please ?

Comment 21

[Dale Harvey (:daleharvey)]

I think this was answered in #834620

With the changes to asyncstorage and initialising hardware asap I dont think there will be many more big wins on the frontend side, the hardware initialisation is still very slow but with front end alone it should feel reasonably fast, if we can speed up the hardware I think it will be genuinely fast

Comment 22

[Dale Harvey (:daleharvey)]

I have been looking into this

with a 4 line script with all the html and css removed that calls the camera as fast as possible, we get the PreviewStream after ~1800ms, with the current code we are around ~2500ms

I investigated both changing the asyncstorage loading and initialising the camera asap and while they both individually had small improvements, together they didnt didnt add up to much of a change, the chances are we were still just contenting for resources before we absolutely needed them.

There isnt any reason we need to be much slower than the 1800ms that a bare script takes us so I will work on that, it isnt going to happen by cherry picking bottlenecks though, to gain 700ms we need to be explicit about making sure we only start loading things until we are outside the fast path, I dont think it needs to be a particularly intrusive change, with all the assets loaded I can still get ~1950ms by directly loading the previewscreen in camera.js

So tl;dr, We should be able to get to the previewstream live in ~1900s which is the fastest we can do with content changes.

mikeh is investigating the driver latency in #821841 but it doesnt look like there is much budge there, if anyone can think of any wins there I think it will make a big difference.

The rest of the time must be spent in dom / gecko land, I will test #821695 to see if it has any significant affect on the camera

Comment 23

[Gabriele Svelto [:gsvelto] (PTO)]

(In reply to Dale Harvey (:daleharvey) from comment #22)
> I investigated both changing the asyncstorage loading and initialising the
> camera asap and while they both individually had small improvements,
> together they didnt didnt add up to much of a change, the chances are we
> were still just contenting for resources before we absolutely needed them.

I think that starting the camera hardware initialization early is still a good idea, here's why: on certain phones the underlying driver is very fast and will be done with the hardware in half a second, on others however it tends to misbehave quite a lot waiting for the hardware in excess of 1s and we have no control over it. Since this code is being run in a separate thread you needn't worry about it, if it's CPU-bound we won't see any speed up but if it just sits twiddling its thumbs waiting for the hardware we have the chance of overlapping quite a bit of work with it.

> [...] with all the
> assets loaded I can still get ~1950ms by directly loading the previewscreen
> in camera.js

That's an excellent number already.

> The rest of the time must be spent in dom / gecko land, I will test #821695
> to see if it has any significant affect on the camera

videocontrols.xml parsing and execution is a very significant addition to both the startup time and frame rendering; see my profiles in bug 834928 comment 3.

Comment 24

[Dale Harvey (:daleharvey)]

Ok, I have an updated pull request on https://bugzilla.mozilla.org/show_bug.cgi?id=833104

Some updated numbers below, the numbers are only inside gaia (dont count process startup), are on the otoro (so worst case) and averages over a few clean runs.

Current Status: 2574.75
Load all assets (do nothing inside camera.js except load preview): 1932.25
No code (no css / l10n, 1 video tag and 6 lines of js): 1726
No code and #821695: 1376

With #833104: 2129.8
With #833104 and #821695: 1722

I will work on 821695 to see how I can help get it landed, I had a few experiments based around https://bugzilla.mozilla.org/show_bug.cgi?id=834620 and they didnt cause much of an improvement, we only have 200ms between no assets vs all assets, but I will try a new version based on top of 833104

Right now we are 400ms away from the absolute bare application (that doesnt load any dom, css or l10n resources etc), I would be surprised if we can squeeze that much more out of gaia, I will attach the 'bare' camera application I was using to test.

Comment 25

[Dietrich Ayala (:dietrich)]

What's the current startup time at now? We need to target 1.5s for partner acceptance.

Comment 26

[Dale Harvey (:daleharvey)]

Depends what is meant for 'startup time', in terms of the load time of the application right now its ~1.1s

https://datazilla.mozilla.org/b2g

that will be reduced down to ~750ms with my patches as far as I can tell, I will be adding a new test to datazilla to see how long until we actually get the preview (which is different and longer than the 1.1s load time)

Comment 27

[[e-mail]]

Yes there could be some difference in the complet startup time which we also call as latency and the load time. 

Today's startup time we measured is 1.8 secs. If we can save that 350ms as mentioned by Dale we would be at less than 1.5 secs which is our first goal.

Comment 28

[Dale Harvey (:daleharvey)]

What are you using to measure startup time?

https://datazilla.mozilla.org/b2g 

Is reporting 670ms average cold startup time, this is just time to load and not time until the preview is shown or time until the use can take a photo

I will add an instrumentation that shows the time taken to show the preview screen hopefully today

Comment 29

[[e-mail]]

We measure the end to end latency from touch start to first full screen update. It is manual testing based on high speed camera.

Comment 30

[[e-mail]]

>> that will be reduced down to ~750ms with my patches as far as I can tell, I 
>> will be adding a new test to datazilla to see how long until we actually get
>> the preview (which is different and longer than the 1.1s load time)

When can we expect this patch?

Comment 31

[[e-mail]]

Also please let share how you you\datazilla measures the load latecy.

Comment 32

[Dale Harvey (:daleharvey)]

The patch landed on master in: https://bugzilla.mozilla.org/show_bug.cgi?id=834620, its not landed on v1.0.1

Datazilla calculates from app launch until the mozbrowserloadend event (which is triggered by an onload)

So it makes sense for your test to be slower, we dont include the time taken for the system to launch the app from the touchdown, and the load event 'may' come after a first paint, when you say 'first paint' do you mean the preview stream or just application paint?

Comment 33

[Andrew Overholt [:overholt]]

ni for comment 32

Comment 34

[Lucas Adamski [:ladamski]]

We need to get to a specific number and methodology before this can be considered a blocking bug.  It can't be fixed without clear success criteria.

Comment 35

[Daniel Coloma:dcoloma]

(In reply to Lucas Adamski from comment #34)
> We need to get to a specific number and methodology before this can be
> considered a blocking bug.  It can't be fixed without clear success criteria.

I agree with Lucas, we should not block on the meta but on specific fixes such as bug 834620, can we unblock on this one?

Comment 36

[Dietrich Ayala (:dietrich)]

Unblocking on metabug per comment #34 & comment #35.

Should we block on bug 821841 then?

Also, how can we resolve the measurement disconnect in comment #32?

Comment 37

[[e-mail]]

>when you say 'first paint' do you mean the preview stream or just application >paint?

For camera application usecase, our team considers tills the start of the camera preview (actual preview frame rendered). 

For other apps, we wait till the full screen update is available like contacts\email loaded in 1 page.

Comment 38

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

(In reply to Gabriele Svelto [:gsvelto] from comment #6)
>
> This application cannot use the prelaunched process like most of the others
> because it needs special permissions to run, see bug 786631. I'm not putting
> it as a dependency because this bug is a blocker and 786631 is not.

Do we still not use the prelaunched process for the camera?  Bug 803471 should have removed the special permissions requirement to access the camera hardware (though we still need direct access to the SD card).

Comment 39

[Gabriele Svelto [:gsvelto] (PTO)]

I just tested on my Unagi and the Camera app uses the prelaunched process. There might have been another bug involved besides bug 803471 to enable this behavior but I can't remember which one.

Comment 40

[Dale Harvey (:daleharvey)]

Closing as these are below required startup time (from previous target)