920713 - Hello World app First Time launch latency regressed

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: Performance, defect, P3)

Description

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

Attachment: helloworld app

We have a test app which prints only "hello world!!!" on display and does nothing. It does not have any JS file. 

We found that launch latency of this app is regressed from 1.1 to master (measured by high FPS camera)

HelloWorld app Launch latency for FFOS 1.1 in QRD 512MB is :

1st launch : 704 ms 
2nd launch : 588 ms

HelloWorld app Launch latency for FFOS 1.2 in QRD 512MB is :

1st launch : 1508 ms 
2nd launch : 1558 ms


So we are seeing a big difference in launch latency. I attached app in this bugid.

Steps to produce in  both FFOS 1.1 and 1.2:
1) Install attached app
2) launch this app and measure launch latency from touchdown to displaying helloWorld

Comment 1

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

Any chance we can get a copy of these videos?

Comment 2

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

It seems to me that TimerTick[1] is not triggered always by timer implementation [2] [3] . This is causing delay in layout Flush_Style for helloWorld app in ICS FFOS 1.2. This seems to me gecko bug in ICS FFOS 1.2. 

[1] http://dxr.mozilla.org/mozilla-central/source/layout/base/nsRefreshDriver.cpp#l180
[2] http://dxr.mozilla.org/mozilla-central/source/layout/base/nsRefreshDriver.cpp#l295
[3] http://dxr.mozilla.org/mozilla-central/source/xpcom/threads/nsTimerImpl.cpp#l546

Comment 3

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

This may affect other app launch as well.

Comment 4

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

(In reply to Mike Habicher [:mikeh] from comment #1)
> Any chance we can get a copy of these videos?

Could you please try to profile it with SPS profiler? There is a visible delay (~700ms) in layout updating.

Comment 5

[Mandyam Vikram]

Analyzing this issue may help undercover a generic issue that could result in overall app launch time improvement for all apps.

Comment 6

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

I just added bug 915083 comment 10, in which I don't see the long camera launch anymore. On inari, today, it's quite snappy. It's kind of an awkward result. I'm pulling a new aurora tree to verify the result.

Comment 7

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

Follow-up to comment 6: the unexplained delay in launching the Camera app comes and goes. I still haven't found a reliable STR, but the delay is either ~1.1s, or nothing. In the 1.1s delay case, none of the threads captured by the SPS profiler appear to be doing anything.

Comment 8

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

(In reply to Mike Habicher [:mikeh] from comment #7)
> Follow-up to comment 6: the unexplained delay in launching the Camera app
> comes and goes. I still haven't found a reliable STR, but the delay is
> either ~1.1s, or nothing. In the 1.1s delay case, none of the threads
> captured by the SPS profiler appear to be doing anything.

Is it related to my observation #comment 2 ? I also saw similar things for hello World app.

Comment 9

[Kevin Grandon :kgrandon]

(In reply to Mike Habicher [:mikeh] from comment #7)
> Follow-up to comment 6: the unexplained delay in launching the Camera app
> comes and goes. I still haven't found a reliable STR, but the delay is
> either ~1.1s, or nothing. In the 1.1s delay case, none of the threads
> captured by the SPS profiler appear to be doing anything.

Are you waiting for the pre-allocated process to launch? You should wait ~10s between relaunches to ensure that the pre-allocated process is ready. If it's not, app launch times can be pretty slow.

Comment 10

[Kevin Grandon :kgrandon]

Hi Tapas,

Could you tell us a bit more about the running conditions of your test? E.g., are you waiting for the pre-allocated process to launch? If you could also attach a profile of the launch that would be extremely useful. Thanks!

Comment 11

[Mandyam Vikram]

The test was not done monitoring the pre-allocated process. This is easily reproducible even after launching the app after many minutes which should not depend on the pre-allocated process.

Comment 12

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

(In reply to Kevin Grandon :kgrandon from comment #9)
> 
> Are you waiting for the pre-allocated process to launch? You should wait
> ~10s between relaunches to ensure that the pre-allocated process is ready.
> If it's not, app launch times can be pretty slow.

Kevin, I typically |adb reboot| the phone, then wait for the Lockscreen to appear, unlock it, swipe left on the Homescreen to get to the first panel of apps, then check |adb shell b2g-ps| to see if "(Preallocated app)" has appeared. Once it does, I could 10 seconds before launching the Camera app.

I've counted 30 seconds too, but it doesn't make any difference.

Comment 13

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

(In reply to Kevin Grandon :kgrandon from comment #10)
> Hi Tapas,
> 
> Could you tell us a bit more about the running conditions of your test?
> E.g., are you waiting for the pre-allocated process to launch?
Yes. I am giving it 1`min . 

> If you could
> also attach a profile of the launch that would be extremely useful. Thanks!

I can see this is taking more time always. There is a visible delay if you compare with two device (running 1.1 & 1.2) and launch the app. 

Can you please launch hello world in both 1.1 and 1.2 . And confirm that you are also seeing same delay .  You don't need high fps camera to confirm. You can confirm with your eyes (~700ms delay).

Comment 14

[Kevin Grandon :kgrandon]

Personally I'm having trouble reproducing this. I definitely see it when the pre-allocated process is not there. If I'm able to see the pre-allocated process using `adb shell b2g-ps`, I don't see these times.

I'm curious if something could be eating your pre-allocated process? Could you verify that you see it using `adb shell b2g-ps`?

Comment 15

[Kevin Grandon :kgrandon]

Assigning to myself, though I'm still having trouble reproducing these times. If anyone else can reliably reproduce these times with the template app or the hello world app, please let me know.

Comment 16

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

Hi, I can always produce this on my device. I want to know which device are you using and also which 1.2 build you tested. Please confirm me. Thanks a lot for your help

Comment 17

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

adb shell b2g-ps ==> also shows me Preallocated process is not killed. Still I see delay :(. Please confirm me your device and 1.2 build revisions (gaia /gecko last commit hash and revision number) .

Comment 18

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

Attachment: b2g18/aurora "Hello, world" comparison data (Inari)

Kevin, here is the data I obtained reproducing this issue on Inari. I got it from a frame-by-frame analysis of the app launches, captured at 240fps on an Olympus Tough 2 camera.

The videos are here:
- aurora: http://people.mozilla.org/~mhabicher/PA111084.AVI
- b2g18: http://people.mozilla.org/~mhabicher/PA111085.AVI

I loaded them into Kdenlive which plays them back at 30fps; the spreadsheet does the timestamp conversion. The launch processes are a bit different between the branches, but the biggest difference is the >1s delay in the aurora build before painting the app background. If we can remove that, aurora will be quite a bit faster than b2g18.

Comment 19

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

Attachment: helloworld app (with JS to log Date.now())

All of my results are obtained using this modified version of Tapas' app, which includes a small bit of JS to dump Date.now() to logcat.

Looking at _just_ the logcat output, helloworld launches ~175ms faster on aurora vs b2g18; the background paint delay kills it.

Comment 20

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

(In reply to Mike Habicher [:mikeh] from comment #18)
> Created attachment 815896 [details]
> b2g18/aurora "Hello, world" comparison data
> 
> Kevin, here is the data I obtained reproducing this issue on Inari. I got it
> from a frame-by-frame analysis of the app launches, captured at 240fps on an
> Olympus Tough 2 camera.
> 
> The videos are here:
> - aurora: http://people.mozilla.org/~mhabicher/PA111084.AVI
> - b2g18: http://people.mozilla.org/~mhabicher/PA111085.AVI

I also saw same delay . Thanks for your help.
> 
> I loaded them into Kdenlive which plays them back at 30fps; the spreadsheet
> does the timestamp conversion. The launch processes are a bit different
> between the branches, but the biggest difference is the >1s delay in the
> aurora build before painting the app background. If we can remove that,
> aurora will be quite a bit faster than b2g18.

Comment 21

[Kevin Grandon :kgrandon]

Still trying to reproduce this, I may need to get an inari device.

In the meantime, if anyone could upload a profile of the app on 1.2 vs b2g18 it would be appreciated.

Comment 22

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

Attachment: b2g18/aurora "Hello, world" comparison data (Hamachi)

An analysis of the high-speed videos here:
- aurora: http://people.mozilla.org/~mhabicher/PA151092.AVI
- b2g18: http://people.mozilla.org/~mhabicher/PA151093.AVI

Touch-event-to-final-display:
- aurora: 1745ms
- b2g18: 962ms

The aurora time includes a >1s delay in getting the final background of the app painted. If this delay were removed, the launch time would be 304ms faster than b2g18. (The b2g18 video also shows a background-paint delay of ~150ms; if that were removed too, the real speed increase would be ~150ms.)

Comment 23

[Kevin Grandon :kgrandon]

Hi Mike, Tapas,

Just wondering if either of you are able to capture a profile of when this issue manifests. The most helpful profile would probably be the following:

1 - Start the profiler (async) of the pre-allocated process, and the b2g process.
2 - Launch the application
3 - Capture the profile

We use this tool to profile: https://github.com/mozilla-b2g/B2G/blob/master/profile.sh

Thanks!

Comment 24

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

Attachment: helloworld profile data.zip

I attached gecko profiler data for helloWorld app launch in FFOS 1.2

Comment 25

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

I did following steps to capture helloworld launch data in #comment 24:

1) ./profile.sh start ==> it reboots b2g process
2) wait for firefox homescreen
3) ./profile.sh signal ==> it captures logs for all pids.
4) launch HelloWorld App and wait till I see final screen
5) ./profile.sh stop ==> it stops capturing
6) ./profile.sh pull <helloworld pid>
7) ./profile.sh symbolicate <filename>

https://developer.mozilla.org/en-US/docs/Performance/Profiling_with_the_Built-in_Profiler

Comment 26

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

Can you please look into it ?

Comment 27

[Kevin Grandon :kgrandon]

Hi Tapas, I'll look into this - but I'm having a hard time extracting useful info from the profile.

Profile of Hello World application from Tapas: http://people.mozilla.org/~bgirard/cleopatra/#report=2f5e28c9aa2925a93018032ab4e0e46762e30ff1

For comparison, here's a profile of our Template app in latest m-c: http://people.mozilla.org/~bgirard/cleopatra/#report=c2c622f17c0a46ec16c85bd7056036399d66f565

Comment 28

[Ben Kelly [:bkelly, not reviewing]]

I don't think you want ./profile.sh stop.  Instead use ./profile.sh capture.

Comment 29

[bhavana bajaj [:bajaj]]

Ni :kgrandon on next steps here, given this is a QC blocker.

Comment 30

[Kevin Grandon :kgrandon]

I'm unfortunately still unable to reproduce this issue on the devices I have with me, so perhaps I am not the best asignee. We are doing a lot of work to make template app startup time *better* though, so I will block bugs against this. I will look for folks on the perf team who are able to reproduce this though.

Comment 31

[Kevin Grandon :kgrandon]

I am tempted to block this bug on 924337 as that bug contains the majority of work to make the template app faster. Most of it seems too risky to uplift to 1.2 at this point though.

Also - it's unlikely that those bugs will fix the ~1s regression noted in the description. I'm still looking for a good profile to diagnose that.

Comment 32

[Mandyam Vikram]

Removing it as a blocker for 1.2 as native apps don't demonstrate this issue.

It should be investigated to understand why this delay is observed on such a trivial app.

Comment 33

[Mandyam Vikram]

@Kevin, can you please expand on what info you are looking from the profiler trace that is missing in Tapas's attachment?

Comment 34

[Kevin Grandon :kgrandon]

(In reply to Mandyam Vikram from comment #33)
> @Kevin, can you please expand on what info you are looking from the profiler
> trace that is missing in Tapas's attachment?

I suppose I'm looking for a profile similar to this: http://people.mozilla.org/~bgirard/cleopatra/#report=c2c622f17c0a46ec16c85bd7056036399d66f565

That is our template application captured with a recent profiler in the B2G repo. :BenWa or :jld would be good folks to ask about profiling.

Comment 35

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

Hi Benoit Girard


Can you please my #comments 25 and let me know what else i need to produce a profiler trace like #comments 34.

Thanks a lot

Comment 36

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

Hi Benoit Girard


Can you please check my #comments 25 and let me know what I need to produce a profiler trace like #comments 34.

Thanks a lot

Comment 37

[Kevin Grandon :kgrandon]

In Comment 32, Mandyam said that we are no longer blocking on this bug, so I'm going to back down to nominate stage and suggest that we do not take for koi.

Also unassigning as I don't have any immediate actionable items on this but, but will continue to look at Template app performance and follow issues in bug 924337.

Comment 38

[Kevin Grandon :kgrandon]

Let me try providing some basic info first, this is how I am able to capture a profile:

Find the process to profile:
    adb shell b2g-ps

Find the pre-allocated process, then profile that PID.
    ./profile.sh start b2g && ./profile.sh start <pid>

Launch the app, then capture:
    ./profile.sh capture

Analyze profile_captured.sym in cleopatra.

Comment 39

[Mike Lee [:mlee]]

Minusing per comment #32 and comment #37.


Tapas,

Is this issue still observed? Latest perf profiling results from you (QC) show launch latencies of all apps on par with 1.1 and better in some cases.

Comment 40

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

(In reply to Mike Lee [:mlee] from comment #39)
> Minusing per comment #32 and comment #37.
> 
> 
> Tapas,
> 
> Is this issue still observed? Latest perf profiling results from you (QC)
> show launch latencies of all apps on par with 1.1 and better in some cases.

Issue is still present for this template 'helloworld' app . But we assumed that it is not affecting other app launches as we are seeing good numbers for other apps (camera, contact, email etc) 

but we are still interested to know what is causing this app to take long time in 1.2 than 1.1

Comment 41

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

I would like to know how are you loading 1.2 build on 1.1 device. Are you doing simple |flash gaia| |flash gecko| ??

If it is so then you will never see this bug. If you flash 1.2 userdata image (using |fastboot flash userdata <userdata image path>|) on 1.1 device then only you can see this bug. 

Please confirm me exact steps by which you are loading 1.2 build on 1.1 device.

Comment 42

[Kevin Grandon :kgrandon]

I generally run the flash.sh script to flash a phone. It sounds like there's a possibility it's not gaia/gecko related - if that's the case it's outside the area of my expertise.

I have sent an email to our perf team seeing if anyone is able to reproduce this, and I will continue to try to work with our team members to reproduce this on our end.

Comment 43

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

@mhabicher : Can you please update with profiler data for this? I am requesting you as I see that you are able to produce it. Thanks a lot

Comment 44

[Lawrence Mandel [:lmandel] (use needinfo)]

Moving to the performance component as this looks to be the domain of the perf team.

Comment 45

[:Eli Perelman]

Closing as bug parameters are outdated, and performance criteria have changed away from the template app to the test-startup-limit app.