817115 - [meta][Gaia::Music] Long initial startup time for Music app

Status: RESOLVED FIXED

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

Description

[Peter La]

What makes it feel slow/broken?
It takes too long to startup the Music app after a reset.  Timed at 5 seconds on Unagi running Nov. 22 nightly.  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:

B2G on Unagi:               5 seconds
Android ICS 4.0.4 on Otoro: 1.5 seconds

David Clarke to provide updated B2G on Otoro numbers.

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

Comment 1

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

BB+, P3 - performance on frequently used Music app

Comment 2

[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 3

[David Scravaglieri [:scravag]]

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

Comment 4

[Gabriele Svelto [:gsvelto] (PTO)]

Here's a profiled run of the Music app starting up with no songs in the /sdcard/Music folder, this was done in order to focus on the application startup time alone:

http://people.mozilla.com/~bgirard/cleopatra/#report=9af970e5bace3e21d2e5e444743a186952489650

The measured startup time is 2.6s which is in the low side, the profile looks quite a bit like that of other well-behaved apps. The only thing that stands out a bit is the time spent on laying out the page which is ~650ms and divided among 5 different chunks, of this ~200ms are spent processing CSS.

I suspect this is due to the layout of the various different panels/visualization modes of the application. It might be worthy - if possible - to load those lazily when the user requests them for the first time instead of at startup. That could save ~400ms or so.

This second trace is done with ~25 songs loaded in the SD card:

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

Measured startup time has gone up by just 150ms to 2.75s which is a very good showing. The profile is mostly unchanged with the biggest major component showing up being the redraw of the tiles; painting each one seem to take 30-50ms but since there's just a handful showing up it doesn't have a big impact on the overall startup time.

The other thing I noticed in both cases is that when going back to the homescreen or when restoring the music app it often flashes completely white before the application content reappears. This seems to happen at the end of the shrinking transaction when going to the homescreen and right after it's been restored to the fullscreen when bringing it up.

Comment 5

[Dominic Kuo [:dkuo]]

Thanks Gabriele, this really helps! I will try to adjust Music app base on the points that you mentioned.

Comment 6

[Alex Keybl [:akeybl]]

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

Comment 7

[Dominic Kuo [:dkuo]]

Bug 814178 is also related to this issue, we also need to consider the scanning behaviour of mediadb to adjust Music app.

Comment 8

[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 believe this is a meta bug and should be bb-.

Comment 9

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

I am unsure what the qawanted is for a meta bug.  Please specify more details in what you want qa to do for this bug if you want to have qa look at it again.  It may make more sense just to do testing/qawanted in the non meta bugs.  (see comment 8)

Comment 10

[Leo]

tef? added as its tricky to follow all dependent defects.

Comment 11

[Lukas Blakk [:lsblakk] use ?needinfo]

As mentioned in comment 8, we need to block the specific bugs that are preventing the ship of v1.0, not the meta bug.

Comment 12

[Ben Francis [:benfrancis]]

Dominic Kuo, do you think there is anything music-specific we can do to improve this further? We're close to partner requirements now but still not quite there.

Comment 13

[Dominic Kuo [:dkuo]]

Ben, yes, I do think there is something we can improve to the Music app.

The first thing popup in my mind is, currently Music will load four pages(Mix, List, SubList and Player) at the initial startup, so maybe we can do such as lazy-loading to the pages when they are needed to show.

And I also noticed that the page transition in Music app can be improved more, because I didn't make sure JS does nothing while page transitioning, that probably will slow down the animation.

I will focus on this issue during the next few days, to see what I can improve more for Music app.

Comment 14

[David Flanagan [:djf]]

Adding bug 834926 to the dependencies list. The fix to that bug substantially improves music scanning time by not creating a thumbnail image for every song. This goes from about 400ms per song to about 250ms per song.

Also adding bug 834957 which optimizes the first scan time for all media apps. This patch (for the first scan) takes us from about 250ms per song to 175ms per song (or something like that).

Comment 15

[Dominic Kuo [:dkuo]]

Just make sure I am on the same page with you guys, I am referencing to:
https://datazilla.mozilla.org/b2g
to see the performance tests reporting of Music app.

And there was a mail thread talking about this issue called "B2G Performance Testing".
In that thread, Dave Hunt said those reports measurement is now based on the mozbrowserloadend event of every app.

Then I tried to enable the "Show time to load" in developer settings, and a TTLView(green log) on the top corner will display the load time of cold[c]/warm[w] boot of every app, I guess the result in the test report should be the same as the TTLView?

I assume the report records every [c] time of Music app, the recorded time should be the event time of "apploadtime"(in system/js/ttlview.js), but I found we often receives the apploadtime event "twice", which was generated by mozbrowserloadend event in system/js/window_manager.js.

If the apploadtime event only fire once normally, the [c] time of Music app looks average to the other apps, about 1327ms, but if the second apploadtime event fires again, the [c] time will increase to about 2729ms, which matches to the report and might explains why the [c] time is relative high to the other apps.

Comment 16

[Dave Hunt [:davehunt] [he/him] ⌚BST]

The results at https://datazilla.mozilla.org/b2g now shows the time until apploadtime for cold starts.

Comment 17

[Dominic Kuo [:dkuo]]

(In reply to Dave Hunt (:davehunt) from comment #16)
> The results at https://datazilla.mozilla.org/b2g now shows the time until
> apploadtime for cold starts.

Thanks Dave, so my assumption should be correct, the results in https://datazilla.mozilla.org/b2g shows the time until apploadtime for cold starts.

In my test, I am pretty sure the apploadtime often fire twice when we cold start an app. If this is a bug, we probably need to fix this or we cannot rely on it to record the cold start time.

Comment 18

[Dave Hunt [:davehunt] [he/him] ⌚BST]

(In reply to Dominic Kuo [:dkuo] from comment #17)
> In my test, I am pretty sure the apploadtime often fire twice when we cold
> start an app. If this is a bug, we probably need to fix this or we cannot
> rely on it to record the cold start time.

The performance tests expect this to only fire once, so it does sound like you've found a bug. :(

Comment 19

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

With a small library, I see a firstpaint startup time for music of around 1.2s, which is respectable but not awesome.

It took me some time to assemble a relatively large library of low-fidelity music files, but let's see how the times change with that ...

Comment 20

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

With a large library (369 songs, 1.6GB),
 - firstpaint is still around 1-1.2s \o/
 - first display of albums, without album art, is ~2.75s
 - first display of album art is ~3.3s
 - full load of all album art is ~4s

So there may be some work we can do here to optimize the order we load albums.

Comment 21

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Profile with latest gecko/gaia, along with profiler goodies

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

Lots of good stuff here.
 - we spend a bunch of time during startup sitting idle.  It looks like we're waiting on IDB and devicestorage queries.  We might be able to reorder those for win.
 - we spend a fair amount of time in tv_update(), apparently creating the album DOM
 - do a relatively expensive restyle/layout/paint, but not unexpected
 - start doing some image decoding
 - then OUCH we spend a bunch of time forcing sync reflows under cropImage()
 - then a bunch of time decoding images and then paint a few times

There's some IDB traffic at the end of the profile that seems to come after all the albums have loaded.  Not sure what that is.

There's not a bunch of low-hanging fruit here, but reordering requests and changing cropImage() might be win.

Prioritizing the load of the initially-displayed albums should help too.  It looks like we might loading and decoding images for all of them.

Comment 22

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Commenting out the code in crop.js saves 300ms on startup.

Comment 23

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

From what I see from experimenting with hacked up non-square album art, the cropImage() function just implements

 background-position: center;
 background-size: cover;

So getting rid of the image load listeners and letting gecko do this computation should be a nice tidy win.

Comment 24

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Attachment: WIP

This replaces the JS reflow logic with CSS and gets rid of <img> tile in favor of CSS backgrounds.  All the ugly sync reflow is gone from the profile, but I'm having trouble measuring startup before/after with a stopwatch.

Comment 25

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

I guess I should split this out from the metabug.  Sec.

Comment 26

[Dominic Kuo [:dkuo]]

After I tested many ways to improve the startup time of Music app, and finally got another patch and looks like a worthy one to apply, I am filing one new bug to attach this patch first, and describe later.

Comment 27

[Dietrich Ayala (:dietrich)]

What startup time are we at now for Music?

Comment 28

[Dominic Kuo [:dkuo]]

(In reply to Dominic Kuo [:dkuo] from comment #26)
> After I tested many ways to improve the startup time of Music app, and
> finally got another patch and looks like a worthy one to apply, I am filing
> one new bug to attach this patch first, and describe later.

I would like to describe what we did in the patch of bug 844029.

The main idea is to hide(use { display: none }) the unnecessary DOM elements of the first sight before music app is launched to improve startup time. The reason why { display: none } works is beacuse while gecko is rendering the elements, the elements with { display: none } will use little rendering costs, comparing to the elements that without { display: none }. I guess gecko will treat those elements just like they are not in the DOM tree yet, cause all the styles are empty. So I just set { display: none } instead of removing the elements from DOM tree before app is started.

Comment 29

[Dominic Kuo [:dkuo]]

(In reply to Dietrich Ayala (:dietrich) from comment #27)
> What startup time are we at now for Music?

With the patch I mentioned above, the startup time gains another 250ms improvement, and plus the lazy loading of some JS in music app, totally the start time improved about 25%.

We can see the latest performance results in the below link:
https://datazilla.mozilla.org/b2g

According to the matic,
The cold_load_time is around: 750 ~ 790ms
The startup_time is around: 600ms

Comment 30

[Gabriele Svelto [:gsvelto] (PTO)]

(In reply to Dominic Kuo [:dkuo] from comment #28)
> The reason why { display: none } works is beacuse while gecko is rendering
> the elements, the elements with { display: none } will use little rendering
> costs, comparing to the elements that without { display: none }.

It might be worth adding this tip to bug 839300.

Comment 31

[Mike Lee [:mlee]]

Following up the only remaining blocker, bug 838063, with Dominic Kuo (dkuo).

Comment 32

[Mike Lee [:mlee]]

Resolving since all dependent bugs have been resolved.