A Quick Update on Snappy Progress

The Performance team has retired the Snappy name, and the individual project leads are now blogging their projects’ progress instead of Taras doing regular Snappy blog posts.

However, I think there might still be some interest in seeing the performance improvements summarized in one place, and since I’m already doing Performance team updates at the Platform meeting, I thought I would try my hand at regularly blogging about ongoing performance work.

So without further ado, these are a few highlights from the past 2 weeks:

  • bug 859558: John Daggett is working on eliminating font jank. The font bugs currently tracked in this meta-bug are top offenders according to chrome-hang reports.
  • Honza Bambas wrote a draft proposal for a new network cache design. The locking in the current network cache is a common source of Firefox jank.
  • bug 830492: Gregory Szorc changed SQLite behavior in FHR to require fewer fsyncs
  • Kyle Lahnakoski developed a tool for comparing Telemetry simple measures. This tool is in the prototype stage and is currently only being used to look for correlations between slow startups and other Telemetry variables (more on that in another blog post). Since Kyle & I are currently the only users of this tool, the page is only accessible from Mozilla’s Toronto network. You will also have to disable mixed-content protection on the page.

A recent bug affected Telemetry submission rates on Firefox 21, 22, and 23 for several weeks. It has since been resolved (bug 844331 and bug 862599), but you’ll need to exercise caution when interpreting dashboard results from the affected time period. Specifically, you may want to exclude data from time periods with relatively few Telemetry submission counts.

Finally, there were several blog posts from the individual project leads:

Current state of Firefox chrome hangs

This post summarizes the top “chrome hangs” reported to Telemetry by Nightly 22 on Windows during the first half of March.

A “chrome hang” is a period of time during which the main thread is stuck processing a single event. It is not a permanent hang. By default, Nightly on Windows reports any chrome hangs lasting at least 5 seconds to Telemetry. You can see your own chrome hangs from your current browsing session in your Nightly’s about:telemetry page.

Data set

There are roughly 270,000 Firefox sessions with chrome hangs in this data set, reporting a total of ~570,000 chrome hang stacks. There are 84,000 “unique” stack signatures, but the heuristic I use for stack signature generation is far from perfect.

The top hangs:

  1. Top 100 stack signatures
  2. Top 50 signatures, excluding plugin hangs*
  3. Top 50 signatures, excluding plugin, GC, CC, HTTP cache, font, or content hangs*

* I removed JS-only stacks that did not contain any useful identifying frames


The raw chrome hang data is challenging to categorize perfectly since there is a very long tail of stack signatures.

Instead, I used a simple heuristic to categorize the stacks, and I found that hang stacks involving plugins are by far the most common (36% of hangs), stacks with font operations are second (12%), GC and CC are third (10%), and the HTTP cache is fourth (4%). The long-tail of “other” operations makes up the remaining 38% of the data.

After filtering the data set to only the top 100 most common hang signatures, I found the distribution of hangs mostly unchanged. Most of the hangs are again caused by plugins: 53 out of the top 100 signatures are plugins (67% by number of hangs). Font-loading operations take second place (11% by number of hangs), followed by GC and CC (9%) and locking in the HTTP cache (4%). The remaining 9% of hangs is mostly made up of long-running JavaScript scripts. Unfortunately, the chrome hang reporting code currently does not  walk the JavaScript stack, so it’s impossible to obtain useful information out of pure JavaScript hangs.

Data: Top 100 chrome hang stack signatures

The plugin problem

We’ve known for a while that plugins are a major source of browser unresponsiveness. In particular, the initial synchronous load of the plugin’s library and the creation of a new plugin instance are the most common hang stacks. The top 100 list also shows plugins taking a long time to handle events and destroy plugin instances. There is also a large number of stacks where Flash hangs cause Firefox hangs on account of Windows input queue synchronization (bug 818059).

Since we’re stuck with the synchronous NPAPI, I suspect we won’t be able to minimize the impact of of plugin hangs until we separate content and chrome into separate processes (i.e. the Electrolysis project). In the short term, we’re mitigating some of the plugin pains by adding read-ahead to improve plugin library loading speed (bug 836488) and starting with Firefox 20, we’re showing users a UI that allows them to terminate an unresponsive plugin after 11 seconds (bug 805591). Both of these patches were written by Aaron Klotz.

Benoit Girard, Georg Fritzsche and Benjamin Smedberg are working on uncovering the causes of some of these hangs by adding profiling support to the plugin-container.exe process (bug 853358 and bug 734691) and exposing IPC message information to the profiler (bug 853864 and bug 853363). You can find Benoit’s write-up here.

Finally, it might also be possible to move some of the heavy plugin operations off the main thread (e.g. bug 856743).


After plugins, font loading operations are the most frequent single category of browser hangs. To see an example of a fonts hang, restart your computer (or clear your OS disk cache by other means) and load the Wikipedia homepage (bug 832546). You should see a hang lasting at least 100ms (depending on your storage device) while the browser loads dozens of fonts from disk to render all the different languages displayed on the page.

There are several existing bugs for font hangs (bug 734308 and bug 699331), but I’d like to ask someone with some knowledge of  the fonts code to file individual bugs for the rest. I filed bug 859558 as a catch-all bug for all the font stacks that I did not recognize.

Data: Top 50 chrome hang stack signatures, excluding plugin hangs

After plugins and fonts, the locking done in the HTTP network cache causes most of the chrome hangs.  It seems the main thread often gets blocked waiting on a lock that is being held by a background cache thread. I assume the background thread is doing disk I/O while holding the contended lock. If you move your Firefox profile to a slow a storage device (e.g. an SD card), you can reliably reproduce these hangs by visiting new sites. The Necko team is currently working on plans for a new network cache design.

Garbage Collection & Cycle Collection are the third most common category of hangs. Surprisingly, incremental GC stacks also show up in the top 50.


In addition to the hangs described above, there is a significant number of  stacks with JIT-ed JavaScript code, page reflows and other content operations. Since chrome hangs don’t report the names of JavaScript functions on the stack and Telemetry doesn’t collect page URLs, these stacks are not useful.  I filtered out these types of stacks and came up with a list of the top 50 “other” hangs.

Data: Top 50 chrome hang stack signatures, excluding common hang types (plugins, GC, CC, HTTP cache, font, content hangs)

This list shows:

  • The JavaScript debugger frequently causes chrome hangs
  • JavaScript calls an nsIDNSService interface function that synchronously resolves DNS names. Could we deprecate use of this function on the main thread?
  • Switching graphics to hardware-accelerated mode after startup (filed bug 859652) and Direct3D device initialization (filed bug 859664) causes hangs
  • Printing causes hangs (filed bug 859655)
  • JavaScript functions called by nsContentPolicy::ShouldLoad take a long time to return
  • DOM workers can take a long time to return the amount of memory in use (filed bug 859657)
  • Extension and chrome JavaScript uses nsLocalFile for main thread I/O. Some of the main-thread calls to nsLocalFile::Exists might be TestPilot main-thread I/O (filed bug 856867)
  • Proxy resolution jank doesn’t seem to have been completely fixed (bug 781732)
  • Destroying CSS style sheets takes a long time (bug 819489)
  • nsSafeFileOutputStream is used on the main thread, blocking the main thread with fsyncs and other file I/O
  • JSON stringify is sometimes called on very large objects
  • Main-thread SQL is a common source of hangs, e.g. nsNavBookmarks::QueryFolderChildren, nsAnnotationService::GetPageAnnotationString, nsDownload::UpdateDB
  • JAR files are opened and closed from the main thread causing hangs

I have not identified all of the hangs in this top list:

  • nsCryptoHash::UpdateFromStream is called from the main thread with a file stream input. I haven’t found the source of this
  • A timer callback evals a string and calls js::SourceCompressorThread::waitOnCompression which causes hangs
  • nsIncrementalDownload::OnDataAvailable writes downloaded data to disk on the main thread
  • nsExternalAppHandler::SaveToDisk moves files on the main thread (known isssue?)


Plugins are the foremost cause of Firefox janks lasting multiple seconds. Fonts, GC/CC, and the HTTP network cache are also common sources. The long tail of hang signatures contains new bugs, some of which could be fixed quickly.


Add-on performance problems

NOTE TO READERS: I wrote this post to draw attention to a common pitfall when using SQLite DBs in extension and Mozilla code. I am not suggesting people stop using the addons mentioned below. The list of top sources of slow SQL is skewed by various factors: more popular add-ons are more likely to be in this list, add-ons that do slow operations against their own DBs will be in the list but add-ons that do slow operations against Firefox DBs will not, etc etc.

The perf team has been using Telemetry data to find and fix performance problems in Firefox code, but the same data can also be used to find performance problems in add-ons.

The Telemetry data on long-running SQL statements, in particular, contains information about slow SQL operations carried out by add-ons. The aggregated reports are publicly accessible from the Metrics dashboard  (BrowserID account needed). If you navigate to the slow SQL section or click on this link directly, you will see stats on SQL statements that took longer than 100ms to execute on the main thread across at least 100 browsing sessions. In general, main thread I/O (including SQL) is a major performance problem in Firefox as the duration of I/O operations is essentially unbounded and any long running operation on the main thread causes browser unresponsiveness. As a privacy precaution, Telemetry never reports statement parameters and only reports the name of the DB if the SQL was executed against an extension DB. Note that the dashboard doesn’t specify whether an SQL string was executed by Firefox or add-on code, but SQL executed against extension DBs has the form “Untracked SQL for <extension DB name>.sqlite”. As can be seen from that dashboard, the majority of main-thread SQL work is still coming from Mozilla code, but addon SQL is well represented.

These are the top 20 addons doing main thread DB work*, found by sorting the slow SQL table on frequency (“Total Doc”):

  1. Various extensions which use the customizable Conduit.com toolbar code. These toolbars sometimes ship with malware, but they also seem to be used in legitimate AMO extensions
  2. The popular ForecastFox weather extension
  3. Fast Dial visual bookmarks
  4. Evernote Web Clipper
  5. Zotero research tool
  6. Mail.ru toolbar
  7. Web.de MailCheck + Mail.com MailCheck
  8. Yoono sidebar
  9. Yandex toolbar
  10. Lazarus form data recovery
  11. DownThemAll! downloader
  12. Xmarks Sync bookmarking
  13. Various extensions using Brand Thunder themes code
  14. Ant Video Downloader
  15. TRUSTe Tracker Protection
  16. a DB which might be associated with PrivacySuite and Targeted Advertising Cookie Opt-Out
  17. GMail Checker
  18. Brief RSS reading
  19. Screenshot Pimp + MediaPimp + Notifications […] for Facebook
  20. Form History Control

* The top offender is actually SQL executed against “cache.sqlite”. This is the name of the DB used by the Lightning calendaring addon for Thunderbird. Its inclusion in the Firefox SQL list might be a bug in the dashboard or it might be an intentionally misleading name for a spyware DB. There were other highly ranked DBs I could not identify: addonstat.sqlite, store-pp.sqlite, livemargins_appcenter.sqlite, database.sqlite.

We will need a joint effort between Mozilla developers and add-on authors to make Firefox snappier for users. Our next step is to reach out to the authors of the above addons and ask them to change how they use SQLite DBs. We’ll also need to improve our documentation on best-practices for extension developers.

UPDATE: A few commenters pointed out that I never mentioned the async SQL APIs in my post. Indeed, developers should be using the asynchronous APIs to execute SQL statements off the main thread: https://developer.mozilla.org/en-US/docs/Storage#Asynchronously

Snappy #46: December Progress

Taras is on vacation this month, so I’m filling in with a Snappy progress update. Taras also has a mini-update on his new blog: Snappy #45: The View From Home.

We are working hard on improving Firefox start up and shut down and much of the work is being done with the help of the new startup & shutdown profiling modes in Benoit Girard’s profiler. In general, we are finding that GC and CC make up a significant fraction of shutdown time. The ongoing exit(0) project is going to be the biggest win for shutdowns, but startup times will likely require many smaller improvements. We also seem to be up against against a gradual and relentless increase in startup times with each release (bug 818257). This may be a consequence of increased code size and our decision to load all of xul.dll on startup.

Over the past month, several patches have landed aiming to improve startup times, but we can’t quantify the user benefits until the server-side bucketing of Telemetry measurements becomes more fine-grained (bug 778809). David Teller made improvements to startup by moving the reading of the session file (bug 532150) and the search bar metadata (bug 760036) off the main thread. Aaron Klotz landed a patch (bug 810101) to read the SafeBrowsing .sbstore and .cache files with the “read-ahead” flag. These files total several megabytes and Aaron’s local testing showed a 50ms reduction in file read times. He also discovered that the .sbstore files get read shortly after startup when we first try to open an HTTP channel.

On the shutdown side, Benoit Girard landed code to skip the destruction of cross-compartment wrappers during exit (bug 818296). He also landed another change (bug 816656) to prevent flushing of the startup cache to disk while shutting down a brief session. Olli Pettay’s bug 818739 stopped the Cycle Collector from being run on shutdown in non-debug builds.

There were also a couple of general responsiveness patches deserving mention: Vladimir Vukicevic landed bug 731974 which promises to considerably improve the smoothness of UI animations, Rafael Espindola moved the reading of a Telemetry data file off the main thread (bug 815709) and Drew Willcoxon refactored the content pref service to use async storage (bug 699859).

James Abbatiello, an external contributor, wrote an extension to track tab switch times to help us identify pages we don’t handle well. The extension adds the last switch time (in milliseconds) to tab titles and shows a full list in an “about:tabswitch” page.  If you’re interested in helping us identify problematic pages, install the Addon Builder Helper and the current draft of James’s extension and consider filing bugs for any URLs which consistently require more than 50ms.

Lastly, I moved LocalStorage writes off the main thread, which ought to provide a relief from a major source of UI unresponsiveness.  LocalStorage has been a top source of slow main-thread SQL for a long time: http://bit.ly/WEOwPC (sort “Latest Changes” section by “Total Sum” column). Honza Bambas is working on a full re-write of LocalStorage (bug 600307) which also adds pre-fetching.

New about:telemetry page in Firefox 19

Firefox 19 now has a built in “about:telemetry” page which displays the data gathered by the “Telemetry” system. If the user has opted in, Telemetry will gather information about Firefox performance, hardware, usage and customizations and submit it to Mozilla. The information in the about:telemetry page is meant to inform users about the data being sent to Mozilla, but it can also help technical users report performance bugs to Mozilla.

For example, the “Slow SQL Statements” section identifies slow SQLite operations which have caused Firefox “jank” (temporary hangs):

about:telemetry "Slow SQL Statements" section

In Nightly builds which support profiling, the “Browser Hangs” section will show call stacks from the main thread whenever it took longer than 5 seconds to process an event. Clicking on “Fetch function names for hang stacks” converts the stack PCs to human-readable function names:

about:telemetry "Browser Hangs" section

The Histograms sections contains various performance and usage measures expressed in histogram form. The histogram data is primarily intended for Firefox developers, but the brave can look up the histogram definitions in Histograms.json and compare their own values to the Firefox population using the Telemetry Dashboard.

about:telemetry "Histograms" section

I invite you to leave a comment or file a bug if there are any changes you would like to see made to the about:telemetry page to make it more useful for you.

Please note that the old about:telemetry extension has been obsoleted by the built-in page and that the extension is now marked incompatible with Firefox 19+.

Cache, plugin, font operations most common in chrome hang reports

A few months ago, in bug 712109, I added functionality for reporting temporary main thread hangs to Telemetry and recently I obtained the first batch of reports. Hang reporting works by monitoring the event loop for inactivity — if the event loop has not started processing a new event for 10 seconds, then the hang monitor will capture a snapshot of the main thread’s call stack and attach the addresses to the next Telemetry report along with the measured duration of the hang. The default minimum hang duration is 10 seconds, but this value is configurable through the hangmonitor.timeout preference. The chrome hang reporter only captures a single snapshot of the call stack, so the captured stack may not always be representative of all of Firefox’s activities during the hang. Generally, it is enough to identify the offending code.

The Hang Reporter Population

Over the 2-month period covered by this batch of data, there were only 42 Telemetry reports containing chrome hangs. This is because hang reporting is only enabled on the nightly-profiling branch as it requires frame pointers for  unwinding the call stack. Additionally, there aren’t many users on the nightly-profiling branch — in fact, yesterday, there were only 14 unique Telemetry submissions by users of the nightly-profiling branch.  Further, we currently don’t save chrome hangs in persistent Telemetry, so some of the reports were likely lost during browser restarts (bug 763113).

Some details immediately jumped out of the hang report data:

  • The median hang duration is 20 seconds.
  • Two underpowered hardware configurations kept popping up in the hang reports, so these two users are over-represented in the data. Together, they contributed 25 of the 42 Telemetry reports.
  • Most Telemetry pings with a chrome hang have only a single hang, but some reports have as many as 10 hangs during a single browsing session.

In order to symbolicate the PCs in the hang reports, we rely on Breakpad symbols. Unfortunately, it seems that symbols for nightly builds are deleted after 30 days, so most of the hangs from April and early May can not be symbolicated. That left 17 Telemetry pings out of 42 whose hangs could be symbolicated. Going forward, the plan is to automate this process and have symbolication done every day (bug 763116).

I think it would also make sense to lower the hang threshold (bug 763124). A threshold of 5 seconds likely wouldn’t overwhelm the Metrics servers even if we deployed hang reporting on the regular nightly channel and it would allow us to detect more subtle performance issues.


Cache Operations

Out of the 33 symbolicated hang stacks, call stacks ending with cache operations are the most common (12 hang stacks). A variety of cache operations are represented in these stacks:

  • nsCacheEntryDescriptor::GetMetaDataElement x3
  • nsCacheEntryDescriptor::GetStoragePolicy x3
  • nsCacheEntryDescriptor::GetDeviceID x2
  • nsCacheEntryDescriptor::Release x2
  • nsCacheEntryDescriptor::GetExpirationTime x2

All of the stacks were reported by a single Windows XP machine, however the reports are over the span of a week and this machine is responsible for almost half of the hang stacks in the entire data set. I think these stacks are a good argument for devoting additional resources to investigating and improving the performance of our caching mechanisms.


The second most common category of hangs are those involving plugins: loading plugins, destroying plugins, setting the window for a plugin and scripting plugins. In each of these cases, the main thread gets stuck waiting for the plugin running in the plugin-container process. It’s not possible to identify the plugin using only the callstack and unfortunately, we currently don’t collect the list of installed plugins.


There were 2 hangs reported while getting font tables. I’ve also recently personally witnessed brief hangs lasting a couple of seconds while fetching the font list. I filed bug 763134.

Excerpt from a sample hang, lasting 16 seconds:

KiFastSystemCallRet (in ntdll.dll)
GDIFontEntry::GetFontTable(unsigned int,FallibleTArray<unsigned char> &) (in xul.dll)
GDIFontEntry::ReadCMAP() (in xul.dll)
gfxFontFamily::ReadAllCMAPs() (in xul.dll)
gfxPlatformFontList::RunLoader() (in xul.dll)
gfxFontInfoLoader::LoaderTimerFire() (in xul.dll)
gfxFontInfoLoader::LoaderTimerCallback(nsITimer *,void *) (in xul.dll)
nsTimerImpl::Fire() (in xul.dll)


The data set contained two hangs where GC took 15 seconds and 31 seconds, and another hang where GC took 24 seconds but it also encompassed destructing an HTML document.


There was a single Telemetry report containing 10 chrome hangs with very similar hang stacks of about ~30 seconds each. All of the stacks had to do with painting gradients via D2D. I think this issue might already be covered in bug 750871.

DrawingContext::FillRectangle(D2D_RECT_F const *,ID2D1Brush *) (in d2d1.dll)
D2DRenderTargetBase<ID2D1BitmapRenderTarget>::FillRectangle(D2D_RECT_F const *,ID2D1Brush *) (in d2d1.dll)
_cairo_d2d_fill (in gkmedias.dll)
_cairo_gstate_fill (in gkmedias.dll)
_moz_cairo_fill_preserve (in gkmedias.dll)
nsCSSRendering::PaintGradient(nsPresContext *,nsRenderingContext &,nsStyleGradient *,nsRect const &,nsRect const &,nsRect const &) (in xul.dll)
nsImageRenderer::Draw(nsPresContext *,nsRenderingContext &,nsRect const &,nsRect const &,nsPoint const &,nsRect const &) (in xul.dll)
nsCSSRendering::PaintBackgroundWithSC(nsPresContext *,nsRenderingContext &,nsIFrame *,nsRect const &,nsRect const &,nsStyleContext *,nsStyleBorder const &,unsigned int,nsRect *) (in xul.dll)
nsCSSRendering::PaintBackground(nsPresContext *,nsRenderingContext &,nsIFrame *,nsRect const &,nsRect const &,unsigned int,nsRect *) (in xul.dll)
nsDisplayCanvasBackground::Paint(nsDisplayListBuilder *,nsRenderingContext *) (in xul.dll)
mozilla::FrameLayerBuilder::DrawThebesLayer(mozilla::layers::ThebesLayer *,gfxContext *,nsIntRegion const &,nsIntRegion const &,void *) (in xul.dll)
mozilla::layers::ThebesLayerD3D10::DrawRegion(nsIntRegion &,mozilla::layers::Layer::SurfaceMode) (in xul.dll)
mozilla::layers::ThebesLayerD3D10::Validate(mozilla::layers::ReadbackProcessor *) (in xul.dll)
mozilla::layers::ContainerLayerD3D10::Validate() (in xul.dll)
mozilla::layers::ContainerLayerD3D10::Validate() (in xul.dll)
mozilla::layers::LayerManagerD3D10::Render() (in xul.dll)
mozilla::layers::LayerManagerD3D10::EndTransaction(void (*)(mozilla::layers::ThebesLayer *,gfxContext *,nsIntRegion const &,nsIntRegion const &,void *),void *,mozilla::layers::LayerManager::EndTransactionFlags) (in xul.dll)
nsDisplayList::PaintForFrame(nsDisplayListBuilder *,nsRenderingContext *,nsIFrame *,unsigned int) (in xul.dll)
nsLayoutUtils::PaintFrame(nsRenderingContext *,nsIFrame *,nsRegion const &,unsigned int,unsigned int) (in xul.dll)
PresShell::Paint(nsIView *,nsIWidget *,nsRegion const &,nsIntRegion const &,bool) (in xul.dll)
nsViewManager::Refresh(nsView *,nsIWidget *,nsIntRegion const &,bool) (in xul.dll)
nsViewManager::DispatchEvent(nsGUIEvent *,nsIView *,nsEventStatus *) (in xul.dll)

It’s also possible that a developer had a debugger attached and that these pauses are from code hitting breakpoints. Telemetry submissions should add a flag to indicate whether a debugger is attached (bug  763138).

Other Hangs

There were half a dozen other hangs in this data set that I still need to investigate further as their causes are somewhat perplexing and I am not familiar with the code in question. For example, in one hang stack, the CreateToolhelp32Snapshot API call used for gathering a list of libraries took 19 seconds while waiting to enter a critical section. In another, it looked like JavaScript ran for 63 seconds without being interrupted by the slow-script dialog box.

If anyone is interested in diagnosing these hangs, I’d appreciate it if you could take a look at the stacks and point me in the right direction or file bugs if you recognize a potential cause. You can leave me a comment on this post below.

These are the remaining stacks: http://people.mozilla.com/~vdjeric/other_hang_stacks.txt


Profiling with the Built-in Gecko Profiler and Local Symbols on Windows

If you would like to use the built-in Gecko Profiler with a local build of Firefox for Windows, you will need to point the profiler to a local Snappy Symbolication Server instead of the official Mozilla symbolication server. The server will host the local Firefox symbols for the profiler and it will fetch any symbols not available locally from the official Mozilla symbolication server (e.g. symbols for Windows DLLs and plugin DLLs).

Instructions: https://developer.mozilla.org/en/Performance/Profiling_with_the_Built-in_Profiler_and_Local_Symbols_on_Windows

Looking at my own about:telemetry data

After I looked at Telemetry data from users with super-slow startups, I decided to take another look at my own about:telemetry page for comparison.

First off, there were 9 SQL statements on the main thread which required longer than 100ms to execute, as well as 46 slow SQL statements on other threads. This is a bit worse than usual for my about:telemetry page + a bit surprising since my machine is a recent i7 laptop with a 7200rpm drive, running on a “maximum performance” power profile. My first suspicion fell on a busy session restore period with 5 windows and ~50 tabs but my browser was not configured to actually load the pages in the background tabs on session restore. I took some comfort in knowing that most of the components which executed those main-thread queries are already being refactored to do async I/O instead.

I was also pretty surprised by the distributions found in a few of the histograms in about:telemetry. My CACHE_DISK_SEARCH histogram, which represents the number of milliseconds to search the disk cache (grouped into buckets), had a surprisingly long tail, with 11 cache reads requiring 100ms or more:

(click for full size)

The CACHE_SERVICE_LOCK_WAIT_MAINTHREAD histogram was also concerning with a few dozen accesses requiring 100ms or more. I didn’t get a screenshot of the original very-long-tail histogram, but I do tend to see this kind of tail show up fairly often:

(click for full size)

This is a known bug and a patch is getting reviewed in bug 722034.
GC_MS is also showing about half the GC operations taking more than 100ms, but  incremental GC is going to be re-enabled soon from what I understand.
Finally, there was the issue of startup time. Startup always takes a few seconds on this machine if I’m restoring a big mess of tabs, but it felt extra slow this time so I took a look at the startup timestamps:
  20ms            main
1856ms            createTopLevelWindow
2806ms            firstLoadURI
4025ms            delayedStartupStarted
4011ms            firstPaint
4060ms            sessionRestoreInitialized
4062ms            sessionRestoreRestoring
4604ms            delayedStartupFinished
6461ms            sessionRestored
We can see a URI being loaded before first paint and adding up to 1.2 seconds to the startup time. I mentioned this in my previous blog post and I’ve filed bug 756313.
In general, looking at about:telemetry can be a bit daunting at first but it can really help narrow down sources of performance problems and give insight into how well the browser is performing in your specific environment. In the near future, we’ll have about:telemetry integrated into the browser (bug 661881) and with a makeover from the UX team, it will get a lot easier to extract meaning & file detailed bugs.

More Telemetry from Super-Slow Startups

Last week, I revisited the issue of super-slow startups by poring over another batch of Telemetry data from February/March of this year. There were 2263 Telemetry submissions matching the following criteria:

  • uptime < 5minutes
  • firstpaint > 30 seconds
  • uninterrupted startup
  • Windows OS
  • containing “appUpdateChannel” field (Firefox 11+)

I further limited my investigation to submissions with fewer than 5 addons, bringing the total down to 1209 such Telemetry submissions — a decidedly small number compared to the number of daily Telemetry submissions over a 2 month period. I was motivated to take another look at super-slow startup reports because Telemetry now reports Firefox startup metrics separately: select performance histograms from startup are now reported separately, as are slow SQL statements from startup.

As in the previous analysis, part of the startup woes seen in these reports can be blamed on Firefox occasionally trying to restore the previous session before painting the UI. There is a fix available in bug 715402 but it hasn’t landed yet. However, my overall impression is that these super-slow startups are primarily caused by very slow computers or computer resources temporarily being in very short supply while Firefox is starting. As such, we may not have many options for helping these users. This is a fairly typical timeline of a very slow startup:

14.406s                         main
51.110s                         createTopLevelWindow
62.344s                         firstLoadURI
62.543s                         delayedStartupStarted
62.547s                         firstPaint
62.584s                         sessionRestoreInitialized
62.614s                         sessionRestoreRestoring
62.684s                         delayedStartupFinished
62.688 s                        sessionRestored

It takes 14 seconds just to reach Firefox’s main and then another 37 seconds to create the top level window, strongly suggesting an over-loaded system. It would be nice if we could confirm this through Telemetry, for example by gathering Firefox page fault stats but it seems that’s pretty tricky to do on Windows. Another very common pattern in the reports (also seen in the sequence above) is that the first real URI (not about:blank) most often starts to load before first paint is complete (filed bug 756313).

Slow SQL statements and other Firefox I/O activities definitely do contribute to the super slow startup times but, as before, their totals are roughly an order of magnitude smaller than the total time required for startup. In particular, STARTUP_NETWORK_DISK_CACHE_OPEN and STARTUP_CACHE_DEVICE_SEARCH frequently appear in super-slow startup reports, contributing several seconds each to startup times. Additionally, MOZ_SQLITE_COOKIES_READ_MAIN_THREAD_MS, MOZ_SQLITE_OTHER_READ_MAIN_THREAD_MS, MOZ_SQLITE_OTHER_SYNC_MAIN_THREAD_MS, MOZ_SQLITE_OPEN_MAIN_THREAD_MS also very commonly report multi-second values. Surprisingly, it also seems very common in these reports for Firefox to read over a megabyte from the cookies.sqlite database during startup alone. This flurry of activity likely comes from the first URI (the homepage?) being loaded and the previous session being restored.

Interestingly, the addons system also seems to be a source of slow main-thread SQL during startup:

  • INSERT INTO locale (name, description, creator, homepageURL) VALUES (:name, :description, :creator, :homepageURL)
  • DELETE FROM addon WHERE internal_id=:internal_id

I believe these SQL statements are associated with addon updates during startup. There may be an opportunity to improve performance by moving more of these operations to a background thread.

Finally, there also appears to be lock contention between the main thread and the async thread on cookies.sqlite DB accesses, e.g. the following statements:

SELECT name, value, host, path, expiry, lastAccessed, creationTime, isSecure, isHttpOnly FROM moz_cookies WHERE baseDomain = :baseDomain

SELECT name, value, host, path, expiry, lastAccessed, creationTime, isSecure, isHttpOnly, baseDomain FROM moz_cookies WHERE baseDomain NOTNULL

This analysis was a lot quicker than the last since I had scripts for sifting through the data and generating the reports. The next step will be to follow up on some of these issues (homepage load before first paint, lock contention, synchronous SQL). Ideally, it will eventually be possible to automate analysis of Telemetry data and have scripts automatically flag troublesome SQL queries or regressions in reported startup times.

Setting up Snappy Symbolication Server locally

UPDATE: If you have been granted access to Mozilla’s jump host, you can create an SSH tunnel to the internal symbolication server:

ssh -L 8000:breakpad-symbolapi1.dmz.phx1.mozilla.com:80 mpt-vpn.mozilla.com -N

You will then be able to use Benoit’s SPS extension and the custom about:telemetry extension out of the box on Windows profiling builds.

UPDATE #2: Refreshed the links to point to a more recent build of Firefox, the old version was incompatible with the latest SPS extensions

In my previous blog post, I gave an overview of the new Hang Detector feature and the Snappy Symbolication Server. Since then, more than one person has asked me for info on deploying the server locally so I’ll reproduce a quick and dirty walkthrough here for easy reference. The instructions below are the minimum required to see a demo of the functionality.

Setting up a profiling Nightly:
1. Download and install the profiling Nightly from March 28th, 2012: https://people.mozilla.com/~vdjeric/firefox-15.0a1.en-US.win32.installer.exe
2. Disable updates in the profiling Nightly from Firefox -> Options -> Options -> Advanced -> Update -> “Never check for updates”.
This will prevent this test version of Nightly from getting out of sync with the debug symbols you will download in the next step.
3. Opt into Telemetry from Firefox -> Options -> Options -> Advanced -> General -> “Submit performance data”. Restart the browser.
4. Install a custom version of the about:telemetry extension: https://people.mozilla.com/~vdjeric/ping.telemetry.xpi

Setting up a Symbolication Server locally:
5. Download some of the symbols for this Nightly profiling build from https://people.mozilla.com/~vdjeric/symbols_ffx.zip. Extract the zip file locally.
6. From Windows command line: “git clone git://github.com/vdjeric/Snappy-Symbolication-Server.git”. You can get “git” for Windows from http://code.google.com/p/msysgit/ or you can install Cygwin.
7. Edit the Snappy Symbolication Server’s “sample.conf” file so that firefoxSymbolsPath and osSymbolsPath point to the “symbols_ffx” directory extracted in step #5. You might also want to set enableTracing = 1 to help with identifying issues.
8. Run the symbolication server locally with “python symbolicationWebService.py sample.conf”. You can get python for Windows from http://www.activestate.com/activepython/downloads or you can install Cygwin.

9. Click on “Force Hang” from the “about:telemetry” URL in the profiling Nightly, acknowledge all alerts. Reload the page and click “Symbolicate Stacks”. You should now see a stack that looks something like this:

Hang report #1 (18 seconds):

??? (in ntdll.dll)
PRMJ_Now (in mozjs.dll)
js_Date(JSContext *,unsigned int,JS::Value *) (in mozjs.dll)

The question marks above are for OS libraries (ntdll.dll) for which you don’t have local symbols and JIT-ed code on the bottom of stack which is not possible to stackwalk reliably.

Note: To generate your own Firefox symbols instead of downloading a sample as above, you’ll first have to make a local debug build of Firefox with an additional “ac_add_options –enable-profiling” line in your .mozconfig. After you’ve built this profiling version of Firefox, you can generate symbols for all your Firefox libraries by running “make buildsymbols” from your object directory.