User:Johnath/startup

From MozillaWiki
Jump to: navigation, search

What We Did

  1. Instrumented the piss out of startup (for our definition of startup) using Vlad's function timer code.
  2. Assembled and annotated a log of that startup to find the major blocks of work. bug 560647

What We Found

Our startup took approx 800ms to get to a boring "waiting for something to happen" event loop. (The log takes 1.4s to get to this point because of ~600ms lost to symbol loading. We've since re-run without symbols to confirm the timings on the sections named below remain accurate, but you can run these timings yourself, too!)

Within those 800ms, here are the areas we expect to contain opportunities for win:

Reflows (10-40%)

Our log shows 21 doReflows of browser.xul after the initialReflow. Initial reflow is 147ms (18% of startup), and the subsequent reflows total an additional 19ms (2.5%).

If other files (hiddenWindow.html, about:blank, home page) are included, the number of non-initial reflows is 36, and the total time is 81ms (10%)

If one naively adds up all the time consumed by functions with "reflow" in their name (FrameNeedsReflow, ProcessReflowCommands, &c), there are 262 calls, totalling 325ms (40%). Paints add another 30ms to this total.

delayedStartup (8%)

In our log, delayedStartup itself takes 65ms (8%), and that likely under-credits things, since it's likely that delayedStartup causes various delayed activities to occur (reflows, new setTimeouts being queued, &c)

The issue of setTimeouts launched from delayedStartup is tracked in bug 568921

XRE_main blocks (14%)

  • pre-XPCOM startup - 17ms (2.1%) - This one can be broken down with more probes - the first probe we inserted in XRE_main was at ScopedXPCOMStartup but significant work is done before that.
  • nsXREDirProvider::DoStartup - 14ms (1.8%) - Half of this is nsExtensionManager.js
  • startupNotifier - 22ms (2.8%) - At least 13ms of this is nsSessionStartup.js
  • post-final-ui-startup churn in XRE_main - 60ms (7.5%) - After final-ui-startup and before Run we lose a good deal of time. This is where ua.css is parsed (called out below), so this block is 70ms of log, but I'm discounting the ua.css time.

Petty Criminals (5-6%)

There are several pieces which take just long enough to be annoying. They are nothing like the ones above, but in aggregate, they are big enough to merit a look.

  • nsContentDLF::CreateXULDocument - 12ms (1.6%) bug 568912
  • GetCMSOutputProfile - 10ms (1.3%) bug 548612
  • Search service init - 9ms (1.1%) bug 568915
  • Parsing gre-resources/ua.css - 10ms (1.3%)
  • Parsing skin/browser.css - 7ms (0.9%)
  • urlclassifier triggering psm init - 6-10ms (0.8-1.2%) In other cases, we've seen this block take 10x this long - plausibly having something to do with the available entropy through the OS. Worth cleaning up regardless. bug 568917
  • Our default Google-hosted homepage triggers more script execution and reflows than necessary. It probably consumes at least a 63ms (8.2%) block of execution, including about 10ms (1.3%) of script execution and 47ms (6.1%) of reflowing. Solved implicitly by bug 563723
  • hiddenWindow.html. The hit from the hidden window varies by platform, but something so empty should really not have much hit at all. We should look at what we want this to accomplish, and make sure it's doing it as minimally as possible.

Our Definition of "Startup"

We:

  • warm-started the browser
  • on a profile with the places_med places database, and
  • some cookies and cache contents accumulated by clicking every link on fark's front page, and
  • session restore including the default home page in a background tab and example.com in the foreground, and
  • a trivial extension installed which overlays browser.xul

We kept the clock running until I could type "google.com<enter>" in the location bar and see a channel open.

Responsiveness side notes

During our instrumentation, we noted that we're spending too much time handling some windows messages. This hurts responsiveness, because the amount of time that we spend handling messages is the amount of time that we don't hit the event loop, and messages caused by user's interaction with the browser window would just get accumulated in the queue without any visible response from the browser. This will cause the browser to feel sluggish.

Some of such messages are:

  • WM_PAINT (28ms, 12ms)
  • WM_LBUTTONDOWN for clicking on the location bar (158ms -- scary!)

Note that we have not attempted to conduct an interaction test, but such tests can be conducted using the same framework.