797395 - Takes about 7 seconds for the settings apps to launch for the first time.

Status: RESOLVED DUPLICATE of bug 920378

(Firefox OS Graveyard :: Gaia::Settings, defect, P3)

Description

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

## Environment :
Otoro phone, build 2012-10-02 us
Taken from default.xml in b2g-distro: 
* "platform_build" revision= 795261940c8b11fb7dddd7a8e9dd8561fdc4fb64
* "gaia" revision= 3e360f0875e519743e2ce3159cbb035d5e8334e1 
* "releases-mozilla-central" revision= 4914d55691e8f602f4275d614183a2cde6aa69db
* "gonk-misc" revision= 202d2c62443c098b125e5d9d7b42226d98230e44
  
## Repro :
1. make sure settings is closed
2. launch settings for the first time

## Expected :
1. settings comes up

## Actual :
1. settings takes about ~ 7 secs

## Note:
* At least 1 banana can be peeled during this time: (bug 796172)

Comment 1

[Gregor Wagner [:gwagner]]

Gabriele started doing some measurements.

Comment 2

[Gabriele Svelto [:gsvelto]]

Attachment: Settings application startup profile

I've attached a quick profile of the settings application during the first launch. Inspecting it with the Cleopatra tool highlights a few hot spots:
- A significant portion of the startup time is spent in network::nsStreamLoader::OnStopRequest() (which in turns spends most of the time in JS::EvaluateString()) followed by a content::nsXMLHttpRequest::OnStopRequest(). During this call all the time is sunk in a js::RunScript() call that - looking at the trace - seems to be dealing with loading and processing i10n resources. Both calls are preceded by two expensive js::RunScript() calls the second of which shows up as BrowserElementChild.prototype._recvGetScreenshot() in the trace. Without knowing the codebase I still can't help wondering what taking a screenshot has to do with a settings application.
- Afterwards a considerable amount of time (~2.5s) is spent in layout::Flush() and more specifically in a long CSS::ProcessRestyles() call followed by an even longer layout::DoReflow(). Comparing the graph with the on-screen behavior makes me think that this is happening during the long pause in which the screen turns dark grey, then white and then displays the actual application
It's the first time I use these tools and I still don't know much about the codebase so please bear with me if my analysis is somewhat simplistic, I will try to obtain a finer grained profile to understand what's going on

Comment 3

[Dave Hylands [:dhylands]]

The screen shot it done so that when you use the task switcher it can show it.

I'd think that taking the screenshot should be deferred until the settings app is at least visible on the display (or until the settings app goes idle).

I'm not sure if we have any idle indication from the content processes, but there is a need for it.

Comment 4

[Gabriele Svelto [:gsvelto]]

(In reply to Dave Hylands [:dhylands] from comment #3)
> The screen shot it done so that when you use the task switcher it can show it.

I see... thanks for clearing that up.

> I'd think that taking the screenshot should be deferred until the settings
> app is at least visible on the display (or until the settings app goes idle).

What's more surprising is that looking at the trace the screenshot happens *before* anything has been drawn (i.e. before the calls to layout::Flush() and Paint::PresShell::Paint()).

> I'm not sure if we have any idle indication from the content processes, but
> there is a need for it.

You mean to defer taking the screenshot to when the application is idle?

On this topic taking the screenshot seems quite expensive, it takes ~400ms on average, with most of the time spent compressing the image into a PNG file and then turning it into a Base64 string (to be fed to sendAsyncMsg). Do we really need to go through such a complicated and CPU-intensive procedure? Skipping the PNG encoding would probably yield significant savings.

Comment 5

[Tim Taubert [:ttaubert] (inactive)]

With bug 804150, the settings app launches in ~4.2 seconds (down from ~6.5 seconds).

Comment 6

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

\o/

We should knock off another 500ms from gsvelto's screenshot work.  What else is left  in the profile?

Comment 7

[Gabriele Svelto [:gsvelto]]

I did another profile run with the latest B2G code, you can find it here:

http://people.mozilla.com/~bgirard/cleopatra/?report=f7e78ce643b1b40e6342a7622cea7e7ab3e70a3e

A few remarks on this trace:

- Screenshot time is now down to ~160ms after applying bug 801676 and we should be able to take it out of the critical path once we find a way to fix bug 799595

- Over one second is spent on a call to layout::DoReflow() (the parameter is the application screen: app://settings.gaiamobile.org/index.html#root), similarly more than one second is spent on a CSS::ProcessRestyles. I get the feeling those need to be fixed in Gaia

- A lot of time (1.5s) seem to be spent loading, parsing and executing JS files. See the two calls to content::nsXMLHTTPRequest::OnStopRequest() and network::nsStreamLoader::OnStopRequest(). The former one is loading internationalization support (I10n.js) and is taking ~900ms, the latter is loading the settings subsections (carrier.js, wifi.js, etc...) and takes ~500ms. Wouldn't it be more efficient to pack all those bits into a consolidated JS file to reduce the overhead?

Comment 8

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

Yep, philikon is looking into .js packing last I heard.

The expensive reflow might be a gecko bug, but it also might be settings using some "slow" selectors.  There are some that are just about impossible to implement efficiently.

Comment 9

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

I believe this is a meta bug since it reference multiple bugs. From what I understood we don't block on meta bug, so let's remove the blocking-basecamp+ flag.

Comment 10

[Mason Chang [Inactive] [:mchang]]

Duplicate of meta bug for settings app launch time.