Telemetry from Super-slow Startups, First Impressions

I have been investigating very slow startups by looking at Telemetry reports of startups taking longer than 30 seconds. There were 49 reports of super-slow startups during a one month period starting Dec 15th that met the following criteria:

• First paint* > 30 seconds
• Uninterrupted startup
• Windows OS
• Recent Nightly or Aurora build reporting on slow SQL Telemetry
• Uptime < 5minutes

* There are 3 metrics used for representing startup speed: “main”, “firstPaint” and “sessionRestore”. The names are mostly self-explanatory, but you can find more detail here.

Two thirds of the slow startup reports had more than 5 addons. While addons may be contributing to slow startups in some cases, there doesn’t seem to be much difference between Telemetry reports for browsers with few addons and many addons. There were also two reports with negative values for uptime (filed bug 722651, similar to bug 670008), but this is a minor bug and not a sign of corruption in the reports.

UPDATE: Some of these reports may come from developer builds with Telemetry manually enabled (Bug 722240) which might explain some of the long startup times. It doesn’t look like there is any way to distinguish local builds from official builds in this dataset (fixed in Bug 720875).

Startup times

The root causes behind the long startups are not immediately obvious from these Telemetry reports. This is partly because Telemetry doesn’t measure everything of interest yet and partly because the Telemetry data was not divided into startup and post-startup measurements (now fixed in bug 720456). Currently, the Telemetry histograms contain measurements both from startup and the initial 5 minutes of browser use.

Most of the startups (as measured by firstPaint) were between 30-60s long. In 32 of the 49 reports, there was a delay of at least 10 seconds before XRE_main was called, perhaps suggesting that these systems were very slow or the startup took place during a time of very high contention for the computer’s resources, perhaps during boot up or a resume from hibernation. In 7 reports, the time to reach XRE_main was even greater than the additional time for producing the first paint. The additional time required for session restore was either negligible (nothing to restore) or surprisingly relatively small compared to total startup time (less than 15%).

One observation of note is that sessionRestore sometimes occurs before firstPaint (bug 715402). This likely further degrades the user experience during slow startups.

Histogram data

The total times recorded by Telemetry histograms in the slow startup reports are not large enough to fully explain the lengthy start up times. The only histograms reporting times on par with the total start up times (or much larger!) are those for:

• asynchronous SQL execution (MOZ_STORAGE_ASYNC_REQUESTS_MS)
• URL classifier work (URLCLASSIFIER_PS_CONSTRUCT_TIME, MOZ_SQLITE_URLCLASSIFIER_READ_MS, …)
• and HTTP page loading (HTTP_SUBITEM_OPEN_LATENCY_TIME, HTTP_SUB_COMPLETE_LOAD_CACHED, …)

None of these operations should be affecting startup times: page-loading should not be happening before first paint (barring bug 715402 above) and URL classifier operations &  asynchronous SQL are executed on worker threads and should not delay startup.

There are, however, a few operations lasting multiple seconds that should not be, such as DWRITEFONT_DELAYEDINITFONTLIST_TOTAL and DWRITEFONT_DELAYEDINITFONTLIST_COLLECT taking 17 seconds each in one report. Similar font performance issues are already being addressed in bug 705594.

The table below shows a few histograms of interest with total times in excess of 1 second during the initial 2-4 minutes:

Although the operations measured by the histograms above are likely not solely responsible for the long startup times, they merit further performance investigation.

Slow SQL data

Adding to the slow system I/O hypothesis, all of the slow startup reports contain multiple SQL statements with execution times over 100ms. Nevertheless, the time taken by these slow SQL statements is still not enough to adequately explain the slow startups.

These are the top 10 most common slow SQL statements across the slow startup reports:

Main Thread

Other Threads

Most of the statements above were executed during regular browser use and not during startup time. Perhaps the most interesting query in the list above is the main thread “PRAGMA page_size” query. It should be a quick read-only query, but in one report it took 4.888s on the main thread while another, more complex query took the exact same amount of time on a different thread. As it turns out, several main thread queries suffer from lock contention with queries on other threads (e.g. bug 722242).

Another interesting point is the factor of 10 or even 100 difference between MOZ_STORAGE_ASYNC_REQUESTS_MS and the slow SQL telemetry times. This is caused by slow SQL telemetry limiting itself to reporting only on prepared statements executed against known Firefox databases. We should also track slow SQL executed from dynamic strings, perhaps by reporting the state of the JavaScript stack instead of the SQL string itself which may contain privacy-sensitive argument values (bug 722368).

Next steps

The obvious next steps are to 1) eliminate the SQL blind spots by tracking times for all SQL executed in the browser and 2) analyze startup data from the most recent Nightlies containing separate startup metrics. I will also be posting more startup analysis from the individual slow startup reports in this batch of data.