Closed Bug 1210440 Opened 9 years ago Closed 9 years ago

Performance regression in Music app

Categories

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

Product:
Firefox OS Graveyard
Component:
Gaia::Music
Platform:
ARM
Gonk (Firefox OS)
Type:
defect

Tracking

(blocking-b2g:2.5+)

Status:
RESOLVED FIXED
Project Flags:
blocking-b2g 2.5+

People

(Reporter: mlien, Assigned: wilsonpage)

References

Details

(Keywords: perf, regression)

Attachments

(1 file)

[gaia] wilsonpage:1210440 > mozilla-b2g:master
46 bytes, text/x-github-pull-request
justindarc
: review+
Details | Review 
On Sep. 28 2015, Raptor detected possible regressions in Music app.
---
Device: Aries-kk
Memory: 2048
Branch: master
---
Music app: regressed by 326ms (grow almost 15%)
---

Gaia revision: a45ba1406decf68f
Previous Gaia revision: d03f6b2dae2499e0

Gecko revision: 6656685be04f907d
Previous Gecko revision: 2bd0998e7c7185d7
Component: Gaia::Music → Performance
[Blocking Requested - why for this release]:

If its specific to an app it should be tracked in the app component.
blocking-b2g: --- → 2.5?
Component: Performance → Gaia::Music
This is when landed the new NGA app: see revision 33381d5a9136e673e50b798ffb7727c2b5c23496
(In reply to Mike Lien[:mlien] from comment #4)
> Also the memory usage grows 16MB from that time, please check with:
> https://raptor.mozilla.org/dashboard/script/memory?var-device=aries&var-
> memory=2048&var-branch=master&var-test=cold-launch

Yes. This is already known. The Music app has been switched out with an entirely different codebase for NGA. We are now tackling perf and bugfixes. Perf/optimization is being tracked in Bug 1209255.
No longer blocks: 1194649
Blocks: music-nga-optimize
Justin, what is plan of optimization in 2.5 or further release? 

According to NGA landed, current number is probably irrelevant with historical regression data. However, we should keep app startup as close as possible with regression line.
blocking-b2g: 2.5? → 2.5+
Flags: needinfo?(jdarcangelo)
Priority: -- → P1
Music NGA landed on the main apps folder on 9/28 and the current numbers (from 10/1) for this NGA app is around 650ms regression on cold launch time from 2.2 release. 

Bobby: the plan is to work on performance optimization (cold launch and memory) in the next 2 sprints along with functional regression bugs. 

Music v2.2 cold launch: 1066ms
Music current cold launch: 1717ms (~650ms regression)
Music v2.2 USS: 13.37MB
Music current USS: 29.49MB (~16.12MB regression)
Assignee: nobody → jdarcangelo
Flags: needinfo?(jdarcangelo)
Summary: Performance regression in Music app from 9/28 → Performance regression in Music app
Now that Bug 1210691 has landed, we should be much closer to the old app's numbers. We still have more optimizations on the way.
See Also: → 1211394
(In reply to Justin D'Arcangelo [:justindarc] from comment #8)
> Now that Bug 1210691 has landed, we should be much closer to the old app's
> numbers. We still have more optimizations on the way.

Cold launch is down to around 1300ms now. Cool! https://raptor.mozilla.org/dashboard/script/measures?var-device=flame-kk&var-memory=319&var-branch=master&var-test=cold-launch&panelId=10&fullscreen
Most of the performance optimizations already landed for Music. Last one pending is the l20n.js optimization. 

Justin, once that lands, please update this bug with the new numbers. 

Thanks
hema
(In reply to Hema Koka [:hema] from comment #7)
> Music v2.2 cold launch: 1066ms
> Music current cold launch: 1717ms (~650ms regression)
> Music v2.2 USS: 13.37MB
> Music current USS: 29.49MB (~16.12MB regression)

There's a problem with these old v2.2 numbers and that is that the v2.2 app has slightly worse numbers when running on latest Gecko:

Music OGA on v2.5 cold launch: 1216ms
Music OGA on v2.5 USS: 16.387MB

Using Music OGA on v2.5 as a baseline for comparison, the NGA app currently measures at:

Music NGA on v2.5 cold launch: 1296ms (80ms regression)
Music NGA on v2.5 USS: 16.676MB (0.289MB regression)

Its clear that there is a Gecko regression involved here too because the Music OGA app on v2.5 should measure almost exactly the same as Music v2.2 (they're the same app). So, taking that into consideration, the NGA app is *almost* on par with the OGA app at this point. There are still additional optimizations in-progress too that should help bring these numbers down even more:

Bug 1213446 - [Music][NGA] Lazy-load tiles in Home view

Bug 1214771 - [NGA] Improve render performance of all list views (for <gaia-fast-list> in general)
I forgot to also mention, we are tracking a power consumption regression as well:

Bug 1214208 - Power Consumption increased in music app while playing music

However, based on https://bugzilla.mozilla.org/show_bug.cgi?id=1214208#c9 it seems as though this is also a Gecko regression related to audio playback/MP3 decoding. It also looks like the offending patch has been identified, so we should hopefully see a patch for this soon.
(In reply to Justin D'Arcangelo [:justindarc] from comment #13)

Excellent progress!
Updated results after landing Bug 1213446:

Cold Launch: 1251ms (35ms regression)
USS: 16.412MB (0.025MB regression)

NOTE: There is still a ~150ms cold launch regression from v2.2 to v2.5 in Music OGA which is likely a Gecko issue. Excluding that, it should be safe to close this bug soon. I would also hold off on closing until Bug 1214208 is resolved.
Hema just let me know that the platform regression that is possibly causing us to lose ~150ms in both the old app and the new app is being tracked in Bug 1207355. Let's re-test once it lands.
Ting, could you help Justin for gecko level profiling? Thanks.
Flags: needinfo?(janus926)
Whiteboard: [Profile-wanted]
https://people.mozilla.org/~bgirard/cleopatra/#report=a94db4a5bdd709201ae03f1412b42d0d17f4f587

I saw a lot of time spending on parsing/executing JS.
Flags: needinfo?(janus926)
Whiteboard: [Profile-wanted]
(In reply to Ting-Yu Chou [:ting] from comment #19)
> https://people.mozilla.org/~bgirard/cleopatra/
> #report=a94db4a5bdd709201ae03f1412b42d0d17f4f587
> 
> I saw a lot of time spending on parsing/executing JS.

Perhaps we can lazy-load more JS.
(In reply to Wilson Page [:wilsonpage] from comment #20)
> (In reply to Ting-Yu Chou [:ting] from comment #19)
> > https://people.mozilla.org/~bgirard/cleopatra/
> > #report=a94db4a5bdd709201ae03f1412b42d0d17f4f587
> > 
> > I saw a lot of time spending on parsing/executing JS.
> 
> Perhaps we can lazy-load more JS.

Is anybody reading my comments!? Running the old v2.2 Music app on master results in a ~150ms regression. This is not a matter of lazy-loading more JS. There is a Gecko regression. Period.

In addition, the NGA app is already lazy-loading everything that could possibly be lazy-loaded.
(In reply to Justin D'Arcangelo [:justindarc] from comment #21)
> (In reply to Wilson Page [:wilsonpage] from comment #20)
> > (In reply to Ting-Yu Chou [:ting] from comment #19)
> > > https://people.mozilla.org/~bgirard/cleopatra/
> > > #report=a94db4a5bdd709201ae03f1412b42d0d17f4f587
> > > 
> > > I saw a lot of time spending on parsing/executing JS.
> > 
> > Perhaps we can lazy-load more JS.
> 
> Is anybody reading my comments!? Running the old v2.2 Music app on master
> results in a ~150ms regression. This is not a matter of lazy-loading more
> JS. There is a Gecko regression. Period.
> 
> In addition, the NGA app is already lazy-loading everything that could
> possibly be lazy-loaded.

Bobby,

Can you please file a separate bug for gecko regression specifically on parsing JS slowness that Ting and others are finding as we profile. Looks like we are seeing this across apps. 

This bug is only tracking new NGA app level optimizations and we have landed everything that we can on the app side. Justin has reported the comparison results with old app (see comment 16). There is no more work happening directly on the new music app for performance at the moment. 

Perhaps it will be clearer if we close this bug and track the gecko specific optimizations that affect multiple apps separately to avoid any confusion. 

Thanks
Hema
Flags: needinfo?(bchien)
Yes, I'm going to close this now. I'm fairly confident that the regression is no longer in the app. The v2.2 app shows the same startup time regression as the NGA app does when running on master.
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Wonder it's

  v2.2 Music + v2.5 Gaia + v2.5 Gecko, or
  v2.2 Music + v2.2 Gaia + v2.5 Gecko

you were testing.
(In reply to Ting-Yu Chou [:ting] from comment #24)
> Wonder it's
> 
>   v2.2 Music + v2.5 Gaia + v2.5 Gecko, or
>   v2.2 Music + v2.2 Gaia + v2.5 Gecko
> 
> you were testing.

Good point. I was using v2.2 Music + v2.5 Gaia + v2.5 Gecko. I'll try and run the numbers for the other combination and see if it makes any difference. Although, I'm not sure anything else in Gaia could be responsible, but you never know :-/
See Also: → 1216406
Separate gecko issue in bug 1216406.
Flags: needinfo?(bchien)
(In reply to Justin D'Arcangelo [:justindarc] from comment #25)
> (In reply to Ting-Yu Chou [:ting] from comment #24)
> > Wonder it's
> > 
> >   v2.2 Music + v2.5 Gaia + v2.5 Gecko, or
> >   v2.2 Music + v2.2 Gaia + v2.5 Gecko
> > 
> > you were testing.
> 
> Good point. I was using v2.2 Music + v2.5 Gaia + v2.5 Gecko. I'll try and
> run the numbers for the other combination and see if it makes any
> difference. Although, I'm not sure anything else in Gaia could be
> responsible, but you never know :-/

Justin, did you verify Gaia and Gecko combination per comment #24 and #25? It's helpful if we could isolate problem in Gaia or Gecko. Many thanks.
Flags: needinfo?(jdarcangelo)
(In reply to Bobby Chien [:bchien] from comment #27)
> (In reply to Justin D'Arcangelo [:justindarc] from comment #25)
> > (In reply to Ting-Yu Chou [:ting] from comment #24)
> > > Wonder it's
> > > 
> > >   v2.2 Music + v2.5 Gaia + v2.5 Gecko, or
> > >   v2.2 Music + v2.2 Gaia + v2.5 Gecko
> > > 
> > > you were testing.
> > 
> > Good point. I was using v2.2 Music + v2.5 Gaia + v2.5 Gecko. I'll try and
> > run the numbers for the other combination and see if it makes any
> > difference. Although, I'm not sure anything else in Gaia could be
> > responsible, but you never know :-/
> 
> Justin, did you verify Gaia and Gecko combination per comment #24 and #25?
> It's helpful if we could isolate problem in Gaia or Gecko. Many thanks.

Apparently, its not possible to run all of v2.2 Gaia on v2.5 Gecko or vice-versa. The best we can do is run the v2.2 *APP* on v2.2 Gaia+Gecko or on v2.5 Gaia+Gecko, which is what I've already done. I am still seeing a ~150ms regression when running the v2.2 APP on v2.5, but I cannot further determine if this is due to Gecko or to some other non-app aspect of Gaia.

Music v2.2 + Gaia v2.2 + Gecko v2.2: 1105.681ms
Music v2.2 + Gaia v2.5 + Gecko v2.5: 1243.356ms
Flags: needinfo?(jdarcangelo)
(In reply to Justin D'Arcangelo [:justindarc] from comment #21)
> In addition, the NGA app is already lazy-loading everything that could
> possibly be lazy-loaded.

None of these scripts [1] are required for first-paint.

[1] https://github.com/mozilla-b2g/gaia/blob/master/apps/music/views/home/index.html#L20-L27
Comment on attachment 8678875 [details] [review]
[gaia] wilsonpage:1210440 > mozilla-b2g:master

BEFORE:

| Metric                | Mean     | Median   | Min    | Max    | StdDev | 95% Bound |
| --------------------- | -------- | -------- | ------ | ------ | ------ | --------- |
| navigationLoaded      | 776      | 776.500  | 750    | 812    | 17.407 | 786.789   |
| navigationInteractive | 804.100  | 805      | 773    | 837    | 18.091 | 815.313   |
| visuallyLoaded        | 1359.500 | 1353.500 | 1330   | 1396   | 23.419 | 1374.015  |
| contentInteractive    | 1360     | 1354.500 | 1330   | 1397   | 23.711 | 1374.696  |
| fullyLoaded           | 1683.500 | 1649.500 | 1582   | 1856   | 85.884 | 1736.731  |
| uss                   | 16.681   | 16.715   | 16.355 | 16.793 | 0.120  | 16.755    |
| rss                   | 36.307   | 36.336   | 35.980 | 36.418 | 0.119  | 36.381    |
| pss                   | 20.845   | 20.892   | 20.485 | 20.983 | 0.136  | 20.929    |

AFTER:

| Metric                | Mean     | Median   | Min    | Max    | StdDev | 95% Bound |
| --------------------- | -------- | -------- | ------ | ------ | ------ | --------- |
| navigationLoaded      | 758.400  | 763      | 672    | 827    | 43.364 | 785.277   |
| navigationInteractive | 785.300  | 789.500  | 705    | 852    | 43.091 | 812.008   |
| visuallyLoaded        | 1262.900 | 1261     | 1194   | 1354   | 36.920 | 1285.783  |
| contentInteractive    | 1263.100 | 1261     | 1194   | 1354   | 36.958 | 1286.007  |
| fullyLoaded           | 1526     | 1521.500 | 1447   | 1664   | 56.178 | 1560.820  |
| pss                   | 20.672   | 20.497   | 19.614 | 21.976 | 0.694  | 21.103    |
| uss                   | 16.490   | 16.314   | 15.402 | 17.785 | 0.687  | 16.916    |
| rss                   | 36.121   | 35.950   | 35.039 | 37.355 | 0.677  | 36.540    |
Attachment #8678875 - Flags: review?(squibblyflabbetydoo)
Attachment #8678875 - Flags: review?(jdarcangelo)
Comment on attachment 8678875 [details] [review]
[gaia] wilsonpage:1210440 > mozilla-b2g:master

Shaves ~90ms off VisuallyLoaded
Reopening to track landing of optimizations.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Comment on attachment 8678875 [details] [review]
[gaia] wilsonpage:1210440 > mozilla-b2g:master

A couple suggested changes:
1.) Get rid of setup() and just make the calls directly from the constructor
2.) Get rid of setupPhase1() and just directly call update()
3.) Rename setupPhase2() to lazyLoadScripts() (or something along those lines)

Otherwise, LGTM! I was trying to avoid lazy-loading WC's because they were sometimes unpredictable if you touched properties on them before they were loaded. But in this case, I think we're safe and it looks like a nice perf-win!
Attachment #8678875 - Flags: review?(jdarcangelo) → review+
Is the stdev for USS pre/post patch reproducible? It'd be concerning how much it increases with the patch :(
Comment on attachment 8678875 [details] [review]
[gaia] wilsonpage:1210440 > mozilla-b2g:master

Addressed comments, waiting for green.
Attachment #8678875 - Flags: review?(squibblyflabbetydoo)
(In reply to Zibi Braniecki [:gandalf][:zibi] from comment #35)
> Is the stdev for USS pre/post patch reproducible? It'd be concerning how
> much it increases with the patch :(

There both ~16. Weirdly in a different order in the output table.
> There both ~16. Weirdly in a different order in the output table.

The value is 16, but stdev is just 100kb in master and over 600kb with your patch. I don't think it should block your patch from landing (memory is overall less stable than perf in our readings), but I'd love to better understand why your patch increases standard deviation 6th fold.
Re-assigning to :wilsonpage since he has a pending patch ready to land.
Assignee: jdarcangelo → wilsonpage
btw. I try to test your patch but the variance in USS results between tests when I just test master against itself is way to high to make test significance, so I'd say we should not read too much into USS numbers. And since it's a perf win here, I believe you should land it.
Wilson's comment 31 already reflect to Raptor[1]. Number is 1244ms.

[1] https://raptor.mozilla.org/dashboard/script/measures?var-device=flame-kk&var-memory=512&var-branch=master&var-test=cold-launch&panelId=10&fullscreen
Flags: needinfo?(wilsonpage)
Priority: P1 → P2
(In reply to Bobby Chien [:bchien] from comment #41)
> Wilson's comment 31 already reflect to Raptor[1]. Number is 1244ms.
> 
> [1]
> https://raptor.mozilla.org/dashboard/script/measures?var-device=flame-kk&var-
> memory=512&var-branch=master&var-test=cold-launch&panelId=10&fullscreen

Raptor tests were run on my device that has a slightly different B2G build and with > 500 songs. So I don't expect the numbers to exactly match the automated Raptor runs. It is clear from profiling that this patch brings a big win by deferring a lot of expensive string evaluation.
Flags: needinfo?(wilsonpage)
(In reply to Bobby Chien [:bchien] from comment #41)

Ah just understood what you meant. I'm pretty sure that perf boost is a result of bug 1210720, which landed yesterday.
AFTER REBASE (inc. bug 1210720):

| Metric                | Mean     | Median   | Min    | Max    | StdDev | 95% Bound |
| --------------------- | -------- | -------- | ------ | ------ | ------ | --------- |
| navigationLoaded      | 764      | 777.500  | 619    | 881    | 62.471 | 802.720   |
| navigationInteractive | 788.700  | 801      | 664    | 901    | 57.196 | 824.151   |
| visuallyLoaded        | 1180.900 | 1183.500 | 1091   | 1263   | 42.871 | 1207.471  |
| contentInteractive    | 1181.100 | 1184     | 1091   | 1263   | 42.943 | 1207.716  |
| fullyLoaded           | 1749.500 | 1737     | 1675   | 1870   | 68.037 | 1791.670  |
| pss                   | 20.948   | 20.893   | 20.144 | 21.617 | 0.418  | 21.208    |
| rss                   | 36.396   | 36.363   | 35.574 | 37.035 | 0.428  | 36.661    |
| uss                   | 16.760   | 16.723   | 15.938 | 17.414 | 0.424  | 17.023    |

---

With this patch and patch from bug 1210720 we should now be beating Music OGA.
Status: REOPENED → RESOLVED
Closed: 9 years ago → 9 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: