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

Any chance we can get a copy of these videos?

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

This may affect other app launch as well.

(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.

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

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.

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.

(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.

(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.

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!

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.

(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.

(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).

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`?

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.

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

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) .

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.

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.

(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.

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.

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.)

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!

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

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

Can you please look into it ?

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

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

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

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.

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.

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.

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

(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.

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

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

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.

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.

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.

(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

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.

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.

@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

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

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