1037706 - [meta][Vertical Homescreen] Improve startup speed after OOM

Status: RESOLVED WORKSFORME

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

Description

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

Easy STR to reproduce this issue:
1) Flash build on device which is memory restricted to use only 256MB.
2) Copy lots of contents to sdcard and launch gallery.
3) You will see gallery is scanning images and now try to zoom in/out an image. This will force to use more memory and device will become slower
4) Minimize gallery and launch camcorder and try to record video
5) Stop recording video and Minimize camcorder.


6) Homescreen will not show any icons for 2-3 seconds . But it will show icons only after 2-3 seconds. 

You need to follow step #3 properly to make sure that you are using lots of memory.


This issue is observed in FFOS 2.0 256MB msm8610 device

This is referenced from bug 1033618 Comment 40

Comment 1

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

it is observed on following 

gaia : https://www.codeaurora.org/cgit/quic/lf/b2g/mozilla/gaia/commit/?h=mozilla/v2.0&id=1bd6e8957ccf310b2f75ba5695b058a2e284df3a
gecko : https://www.codeaurora.org/cgit/quic/lf/b2g/mozilla/gecko/commit/?h=mozilla/v2.0&id=7a31c320cc1ea4ca6393634a17cfd575d17b035d

Comment 2

[Kevin Grandon :kgrandon]

Sounds like we should grab a profile here. I'm traveling over the weekend, so not sure if I can do it until early next week.

Comment 3

[Kevin Grandon :kgrandon]

Also just to be clear here in this case I think we OOM everything and take the pre-allocated process as well, at least that's what we were seeing in the other bug. So I would imagine that this is the same as starting up the homescreen without a pre-allocated process. We should verify that though.

Comment 4

[Benoit Girard (:BenWa)]

Yes, the background will still show up if the homescreen has been killed but the icons will not. Make sure that the Homescreen process is still running before minimizing the app. If it is not it is expected that the homescreen will take a few seconds to launch. Particularly if the preallocated process has also been killed.

Comment 5

[Kevin Grandon :kgrandon]

Like Benoit said, this is probably expected if we don't have a preallocated process. I guess we should do a test of the 1.4 homescreen under similar conditions. We should probably check the 1.4 homescreen running on the gecko for 1.4, and running on the gecko for 2.0

Comment 6

[Gregor Wagner [:gwagner]]

qawanted for comment 5.

Comment 7

[bhavana bajaj [:bajaj]]

NI :johan for qawanted request here.

Comment 8

[Andreas Gal :gal]

I have seen the icons load pretty slowly in general. We should find out why. I often see the icons take 500ms to redraw when the lockscreen disappears. Why?

Comment 9

[Kevin Grandon :kgrandon]

(In reply to Andreas Gal :gal from comment #8)
> I have seen the icons load pretty slowly in general. We should find out why.
> I often see the icons take 500ms to redraw when the lockscreen disappears.
> Why?

We have bug 1038500 for the redraw after the lockscreen (deemed non-blocking in the original bug).  I have a feeling that bug 1038500 is about recovering from setVisible() being false, and this bug is about raw performance when launching without a pre-allocated process. We should figure out if it's the same issue, there may be some fixes that improve both.

Comment 10

[Johan Lorenzo [:jlorenzo]]

Attachment: about-memory.zip

On the 273MB Flame with today's build, no need to run the camera to trigger that behavior, you just need to:
1. run the gallery with more than 40 pictures
2. zoom in one of them
3. wait until the zoom is completed
4. hit the home button

I checked with :gerard-majax that the Homescreen is killed when you zoom the picture. 

Here is attached an about:memory just before zooming the picture.

Comment 11

[bhavana bajaj [:bajaj]]

Kevin comment #10 has reduced STR here, let us know if you need anything more to get this investigated.

Comment 12

[bhavana bajaj [:bajaj]]

Kyle mentioned we could get some profiling done here, Also spoke offline with :kgrandon and he can help get the investigation started, so passing this to him for now.

Comment 13

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

(In reply to Johan Lorenzo [:jlorenzo] from comment #10)
> Created attachment 8456092 [details]
> about-memory.zip
> 
> On the 273MB Flame with today's build, no need to run the camera to trigger
> that behavior, you just need to:
> 1. run the gallery with more than 40 pictures
> 2. zoom in one of them
> 3. wait until the zoom is completed
> 4. hit the home button
> 
> I checked with :gerard-majax that the Homescreen is killed when you zoom the
> picture. 
> 
> Here is attached an about:memory just before zooming the picture.

Thanks for profiling this. We are also seeing same issue. Please let us know if you still need any kind of logs from us.

Comment 14

[Kevin Grandon :kgrandon]

I am not really looking at a fix for this yet, so anyone is free to steal if they feel inclined to do so.

Comment 15

[Kevin Grandon :kgrandon]

Benoit - can you point me to some steps about how to profile app launch when there's no pre-allocated process? For app launch, I generally profile the pre-allocated process, but in this case I believe the OOM is taking it out as well. Is there any way to monitor this? Thanks!

Comment 16

[Benoit Girard (:BenWa)]

You have two options:
- Hardcod patch profiler_init to start the profiler when it matches a condition you can easily detect about the particular process.
- Export MOZ_PROFILER_STARTUP (and similar startup variable to tweak the start options if the defaults aren't good). It's best if you can only set it for the particular process but if it difficult option 1) might be easier if you can find something to detect that you're starting the app that you want. If you can't then profiling all processes shouldn't be -that- bad but it's not ideal.

Once it's running profile.sh ps/capture should work just fine.

Comment 17

[Lucas Adamski [:ladamski]]

FWIW for me, 2.0 often takes around 500ms to draw homescreen icons when existing any app say the email app with no memory pressure (even under 1GB).  Doesn't happening when unlocking, so that's odd.

Consistent STR with 2.0 and 1GB (or less):

- kill all apps
- launch email with some account(s) setup (ok to wait for it to load and sync)
- hit home button
- get homescreen with app titles but no icons for about 500ms

Comment 18

[Kevin Grandon :kgrandon]

Documenting this quick script to help me get into a similar state. This kills both the pre-allocated process and the homescreen process. Someone let me know if there's an easier way :)

adb shell b2g-ps | grep 'Preallocated a' | awk {'print $4'} | xargs adb shell kill -9 && adb shell b2g-ps | grep Homescreen | awk {'print $3'} | xargs adb shell kill -9

Comment 19

[Kevin Grandon :kgrandon]

If we are happy with the current 1.4 homescreen launch speed, then this bug is about launch time of the vertical homescreen.

I'm seeing that we get our initial rendering call around ~2,300ms after launch. I'm guessing the slowness here is due to how we wait for the datastores to syncronize before we call render. Let's see if we can be smarter about async things, especially since we already cache the icon.

Comment 20

[Kevin Grandon :kgrandon]

This is linear with object count it seems, on a vanilla homescreen I'm seeing ~1.6s to load after we start parsing, which doesn't seem too bad to me. Also, since the recent memory fixes in homescreen and in the media apps the homescreen will be OOM'd a lot less now. 

I think we can get better at this, but I'd like to re-consider for blocking as we don't have enough information here, and this should happen less. My recommendation is to mark as 2.0- for now, but if this si still awful, I think we'd need the following information to block:

1 - How often does this happen when using the phone during typical use cases?
2 - What kind of goal are we looking at here? I feel that startup time is along the lines of typical apps, but maybe the performance team can tell us more.

Comment 21

[Kevin Grandon :kgrandon]

If we do end up needing this, I'm going to recommend that we first land and uplift bug 972076 and bug 903291. These will improve the load time of the homescreen by several hundred ms.

Comment 22

[Kevin Grandon :kgrandon]

The alternative to uplift would be to instead attempt to cache everything in mozApps, and multiple datastores in our local indexedDB. This is likely going to cause more memory problems as we load/populate objects, and have logic for synchronizing updated objects to the database. Due to the memory battles we have fought so far, and our experience with the old homescreen, uplifting bug 972076 would be the way to go.

Comment 23

[Gregor Wagner [:gwagner]]

How risky is the uplift of bug 972076?

Comment 24

[[:fabrice] Fabrice Desré]

(In reply to Gregor Wagner [:gwagner] from comment #23)
> How risky is the uplift of bug 972076?

It depends on bug 903291 which is too risky to uplift (we're still fighting with test failures). So not possible so late unfortunately.

Comment 25

[Inder]

> 
> 1 - How often does this happen when using the phone during typical use cases?

Considering we are constrained by 256MB memory and we are getting OOM situations more often due to new features, likelihood of this happen is quite often.

> 2 - What kind of goal are we looking at here? I feel that startup time is
> along the lines of typical apps, but maybe the performance team can tell us
> more.

HS performance of 2-3 sec startup is definitely bad and more noticeable so we should definitely improve it.

Comment 26

[bhavana bajaj [:bajaj]]

(In reply to Kevin Grandon :kgrandon from comment #20)
> This is linear with object count it seems, on a vanilla homescreen I'm
> seeing ~1.6s to load after we start parsing, which doesn't seem too bad to
> me. Also, since the recent memory fixes in homescreen and in the media apps
> the homescreen will be OOM'd a lot less now. 
> 
> I think we can get better at this, but I'd like to re-consider for blocking
> as we don't have enough information here, and this should happen less. My
> recommendation is to mark as 2.0- for now, but if this si still awful, I
> think we'd need the following information to block:
> 
> 1 - How often does this happen when using the phone during typical use cases?
> 2 - What kind of goal are we looking at here? I feel that startup time is
> along the lines of typical apps, but maybe the performance team can tell us
> more.

NI :mlee here to see here if we can get more granular measurements here, but this seems a bad start-up for Homescreen ..

Comment 27

[Kevin Grandon :kgrandon]

There is likely a lot of small wins we can do on the homescreen side and platform side for this. As no one patch will solve it, marking as a meta.

Comment 28

[Gregor Wagner [:gwagner]]

We don't block on meta-bugs. Lets nominate all the important blocking bugs here.

Comment 29

[Jason Smith [:jsmith]]

(In reply to Gregor Wagner [:gwagner] from comment #28)
> We don't block on meta-bugs. Lets nominate all the important blocking bugs
> here.

Typically this is true. However, performance bugs are a bit different. Usually the blocking flag is included on the bug because it's tracking a symptom towards a goal we must reach in order to pass certification. If it makes things easier to fix things in parts, then we should open up dependencies for what is needed to fix the problem. However, we do need a way to track the resolution of the problem against the actual symptom of the problem under the blocking list. Otherwise, I am concerned this could fall through the cracks, as we do not have a clear way of understanding what performance symptoms must be fixed in order to ship a particular release.

Does that make sense?

Comment 30

[Inder]

Totally agree with Jason. We need to track this issue for 2.0 and have it fixed. This is an issue we opened which got converted to a metabug and now none of the dependent bugs here are slated for 2.0.
So, without a solution we are removing this bug from 2.0 blocking!

Comment 31

[Gregor Wagner [:gwagner]]

Alright lets block on the meta bug again. Kevin, can you work with the perf team to get a CPU profile here?

Comment 32

[Kevin Grandon :kgrandon]

I will take a look, but I'm still not convinced that we can block on such a bug without any targets. Ideally we would like apps to launch and be ready within ~1s, but that is not the case today [1]. It looks like the settings app is visually complete at about ~3s sms around ~2.5s, and several apps below 1s. 

Mike - can you weigh in with what our blocking criteria should be? Looking at the datazilla visually complete chart, I would say that "under 2 seconds" for visual completion would be a good target to block on. 

https://datazilla.mozilla.org/b2g/?branch=master&device=flame&range=7&test=startup_%3E_moz-app-visually-complete&app_list=bookmark,browser,calendar,camera,clock,communications/contacts,communications/dialer,communications/ftu,contacts,costcontrol,email%20FTU,emergency-call,findmydevice,fm,fm_radio,gallery,homescreen,marketplace,messages,music,operatorvariant,pdfjs,phone,pss,rss,settings,sms,system_pss,system_rss,system_uss,system_vsize,template,usage,uss,video,vsize&app=settings&gaia_rev=6c85ca2112b45b27&gecko_rev=6e1849b0b978&plot=avg

Comment 33

[Inder]

Tapas -- can you please try out the patch from bug 1041291 and see where we stand?

Comment 34

[Lucas Adamski [:ladamski]]

Can we get some realistic criteria here (put it in the user story field I guess!) so we can determine when this bug has been fixed?

Comment 35

[Mike Lee [:mlee]]

(In reply to Kevin Grandon :kgrandon from comment #32)
> ...
> Mike - can you weigh in with what our blocking criteria should be? Looking
> at the datazilla visually complete chart, I would say that "under 2 seconds"
> for visual completion would be a good target to block on. 

Criteria is documented on our Performance wiki [1]; 1s for visually complete. Metrics for Homescreen are being implemented in Bug 1042563.

[1] https://wiki.mozilla.org/FirefoxOS/Performance/Release_Acceptance

Comment 36

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

I really doubt that 1s is a realistic number to block on.

Comment 37

[Kevin Grandon :kgrandon]

(In reply to Kyle Huey [:khuey] ([e-mail]) from comment #36)
> I really doubt that 1s is a realistic number to block on.

For cold launch time (which I think is different than visually complete), I think 1s is reasonable. I guess I'm not sure if cold launch time is inferring visually complete here. In the past cold launch time was basically only until the load event - and I think we get that within 1s today.

Mike/Eli - Any comment if cold launch time on the wiki infers visually complete? Can we update the wiki to be more clear, and potentially leverage the new events?

Comment 38

[:Eli Perelman]

Cold launch times are technically going to be calculated based on the moz-app-visually-complete event, but you're right, it's not very apparent on that page. Here is a link to the MDN article which I will post on the criteria page, and make a statement about the event that is tied to the official launch time.

https://developer.mozilla.org/en-US/Apps/Build/Performance/Firefox_OS_app_responsiveness_guidelines#Goals

Comment 39

[Kevin Grandon :kgrandon]

(In reply to :Eli Perelman, Paris Jul 21-25 from comment #38)
> Cold launch times are technically going to be calculated based on the
> moz-app-visually-complete event, but you're right, it's not very apparent on
> that page. Here is a link to the MDN article which I will post on the
> criteria page, and make a statement about the event that is tied to the
> official launch time.

Ok, this is confusing because cold launch times *today* on datazilla are based on the onload event, and not visually complete. I'd recommend for us to stop referring to cold launch time if it's not an actual perf stage event. In any case, I'm updating the link in the user story to point to the mdn page.

The posted page does show a 1s visually complete state, which will be fairly difficult for the homescreen in 2.0.

Comment 40

[:Eli Perelman]

Correct, launch times (cold load time) *today* are based on cold_load_time generated by b2gperf which are based on onload. Once we are ready to flip the switch on the new launch times from bug 996038, cold load will be changed to be "moz-app-visually-complete" and transitioned away from onload.

I spoke to Kevin offline, and something important to note is that apps are currently tested for launch times by having a pre-allocated process. This will also be the way we write the test against the home screen, so while 1000ms is still the goal for cold load time for the home screen, this will be against a pre-allocated process. Making measurements for the home screen when OOM-killed with no pre-allocated process must have some allocated above 1s, but what that goal looks like I don't have the exact answer for as of yet.

Comment 41

[Kevin Grandon :kgrandon]

(In reply to :Eli Perelman, Paris Jul 21-25 from comment #40)
> Correct, launch times (cold load time) *today* are based on cold_load_time
> generated by b2gperf which are based on onload. Once we are ready to flip
> the switch on the new launch times from bug 996038, cold load will be
> changed to be "moz-app-visually-complete" and transitioned away from onload.

Sure, I would suggest just dropping the concept of cold load time instead of changing what it's measuring as that might cause more confusion like what we have in this bug. Just stick to your new perf events and we should be good (You can measure both cold and warm for each event if you wanted).

Comment 42

[Kevin Grandon :kgrandon]

The following timestamps are taken from the start of the vertical homescreen until render. I'm updating the user story to include these so people can find them easily.

Timestamps taken from master:
Debug engineering profile: ~1230ms
Production build, /w 47 apps total: ~985ms
Production build, 18 apps: ~700ms

Timestamps taken from 2.0 with 2.0 gecko and master gaia:
Debug engineering profile: ~1700ms
Production build, /w 47 apps total: ~1470ms
Production build, 18 apps: ~1100ms

A few interesting things to note:
1 - 2.0 is 500ms slower than master, with the same gaia.
1 - We save ~250ms due to the minified sources on the device with PRODUCTION=1 profiles.
2 - The number of apps currently has an impact on startup. We see a delay of ~10ms per additional app in startup time.

Right now I feel like if we're missing some gecko patches in 2.0. We should uplift them and things will be much better, probably enough to resolve this bug. Next steps are to dig in and see what gecko patches have improved the 500ms.

Comment 43

[Kevin Grandon :kgrandon]

Updating metrics in user story to clarify that these numbers were taken with a 273mb memory constrained flame.

Comment 44

[Kevin Grandon :kgrandon]

Adding some notes about mozApps latency during startup. According to my measurements, it appears that some of the gain comes from there, and at best case we could gain ~300ms if we uplifted everything to 2.0. This leaves still ~200ms unaccounted for in master compared to 2.0, so I will next try to gather some profiles to see where the extra time is being spent.

My methodology for debugging this was inserting a performance.now() call before the getAll() call and another in the onsuccess handler.

Master Mozapps getAll() performance: between 140ms and 320ms
2.0 Mozapps getAll() performance: between 300ms and 460ms

Comment 45

[:gerard-majax]

Kevin, investigating bug 1038884 I could document some startup allocation in https://bug1038884.bugzilla.mozilla.org/attachment.cgi?id=8463302

Not only we constantly allocated 1560KB twice for "nothing", but I have constantly seen a slight delay in the performed measures when those allocations were reproducing. Maybe as in bug 1038884 comment 104 we can gain some things from bug 1024148 ?

Comment 46

[Kevin Grandon :kgrandon]

Thanks for the info. I will try to apply the patch from bug 1024148 if there are not too many conflicts to get some measurements. Otherwise let's see if we get blocking status on that one and see impact after uplift.

Comment 47

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

(In reply to Kevin Grandon :kgrandon from comment #46)
> Thanks for the info. I will try to apply the patch from bug 1024148 if there
> are not too many conflicts to get some measurements. Otherwise let's see if
> we get blocking status on that one and see impact after uplift.

bug 1024148 has already landed and we are still seeing a big difference of homescreen startup time between v2.0 and v1.4 .

Comment 48

[Kevin Grandon :kgrandon]

I am nominating this again to put this back into triage.

Since this is a meta bug there is not much actionable here. We have identified everything that will impact and help this, and if all of the blocking bugs are solved, this one will be as well. I recommend not blocking, and instead nominating the dependent bugs.

Comment 49

[bhavana bajaj [:bajaj]]

(In reply to Kevin Grandon :kgrandon from comment #48)
> I am nominating this again to put this back into triage.
> 
> Since this is a meta bug there is not much actionable here. We have
> identified everything that will impact and help this, and if all of the
> blocking bugs are solved, this one will be as well. I recommend not
> blocking, and instead nominating the dependent bugs.

Can you nominate the individual dependencies that will help here ? Look at https://bugzilla.mozilla.org/show_bug.cgi?id=1037706#c30 for the reason we might still need to block here until we see which of the dependencies is fruitful and helping this metabug.

Comment 50

[Kevin Grandon :kgrandon]

(In reply to bhavana bajaj [:bajaj] from comment #49)
> Can you nominate the individual dependencies that will help here ? Look at
> https://bugzilla.mozilla.org/show_bug.cgi?id=1037706#c30 for the reason we
> might still need to block here until we see which of the dependencies is
> fruitful and helping this metabug.

If we solve all of the dependent bugs, than this one will be solved as well. Bug 1045842 is the most fruitful bug, and is already blocking 2.0.

Comment 51

[bhavana bajaj [:bajaj]]

(In reply to Kevin Grandon :kgrandon from comment #50)
> (In reply to bhavana bajaj [:bajaj] from comment #49)
> > Can you nominate the individual dependencies that will help here ? Look at
> > https://bugzilla.mozilla.org/show_bug.cgi?id=1037706#c30 for the reason we
> > might still need to block here until we see which of the dependencies is
> > fruitful and helping this metabug.
> 
> If we solve all of the dependent bugs, than this one will be solved as well.
> Bug 1045842 is the most fruitful bug, and is already blocking 2.0.

Setting this meta as blocking as discussed in the call until we are sure the dependencies land and the goal is met.

Comment 52

[Brogan Zumwalt [Inactive]]

New test case needs to be written

Comment 53

[KTucker [:KTucker][Inactive 3/4/2016]]

New test case created in moztrap:

https://moztrap.mozilla.org/manage/case/14236/

Comment 54

[Tapas[:tkundu on #b2g/gaia/memshrink/gfx] (always NI me)]

Delay is still 2 sec (stop watch measurement) in following gaia/gecko

https://www.codeaurora.org/cgit/quic/lf/b2g/mozilla/gaia/commit/?h=mozilla/v2.0&id=88e774c606520c9ce349b467866e200e8db31af4
https://www.codeaurora.org/cgit/quic/lf/b2g/mozilla/gecko/commit/?h=mozilla/v2.0&id=7f737a23c72e0dff6dd2cba67ee0df24d00223a1

Comment 55

[Kevin Grandon :kgrandon]

Ok, thanks for the info Tapas. From our call it seemed like this was going to be punted to 2.1 to work on then as any patch we provide now would be risky for stability. I'll wait for you to confirm the plan here.

Comment 56

[Inder]

[Blocking Requested - why for this release]:

In offline discussions it came up that any changes we can do for 2.0 is risky at this point so moving the requirement to 2.1.

Comment 57

[Kevin Grandon :kgrandon]

Let's do some work here in 2.1 for this. Blocking vhomescren.next instead of the qa metabug.

Comment 58

[Dave Huseby [:huseby]]

I ran some timing on the cold launch time of the vert home screen with an engineering profile.  This was made by restarting b2g and timing from the point where the vert homescreen process is created to the time the renderGrid callback happens in JS.  Here's my measurements:

1339
1410
1381
1398
1279
1366
1361
1421
1293
1381
1326
1351
1290
1270
1443

mean: 1353
std dev: 54

This was on a 319MB flame running the latest v2.0 as of Thursday (8/15/14).  These numbers look very close to the original numbers in Comment 0.

Comment 59

[Kevin Grandon :kgrandon]

2.1 is looking much better than 2.0. I'll try to get some numbers today to see if this is still needed.

Comment 60

[Kevin Grandon :kgrandon]

Based on the measurements in the user story we currently startup a PRODUCTION build of the homescreen in < 1000ms. This is ~400ms faster than 2.0 and meets our performance goals.

Tapas - Can you test 2.1 startup time? If it's not sufficient, we should create a new bug as this one has a lot of information specific to 2.0.