In a previous blog post I asked for volunteers to send in their shutdown profiles automatically. I’ve received hundreds of slow shutdown profiles, 30 profiles of which are over 10 seconds and one as high as 80 seconds! These profiles show us where Firefox is spending its time when closing down to the millisecond.
Before I started this experiment I asked around for what people thought was the cause of the slow shutdowns. The overwhelming response I got was that it was Garbage Collection and Cycle Collection. While those operations do make the shutdowns slower, they were rarely responsible for those 10 to 80 seconds shutdown times.
Here’s some interesting issues we found:
- A few start-up optimizations moved operations off the startup path and into timers that would update the startup cache, or load fonts. These timers were never canceled when shutting down so they would lead to things such as font loading while shutting down. Since you have to open & close the browser within a minute to see these issues they are not critical for our users but these are certainly bugs we are cleaning up. Keep in mind if you are running timers you should stop them on shutdown before they fire if they are no longer useful.
- On a related note we have timers going off during the shutdown. Particularly GC and CC timers. There is no guarantee that the shutdown will take long enough for these timers to run. If these are useless then we will waste time but if they are important they may not run.
- Stopping plug-ins can take up to a second. I do not capture what is happening in the plug-in process so I can’t tell if it’s our container or the plug-in.
- Releasing style sheets on shutdown will sometimes total over 1 second of execution on slow shutdown.
- Time spent in sqlite3close in some profiles is as high as 10 seconds.
- Bookmark backups are hurting us.
A big thumbs up to people who are submitting shutdown profiles. The data we are collecting is very valuable in helping us understand how Firefox behaves outside the labs.
This weekend GTest landed in the mozilla-central tree. See Bug 767231 for the changes and follow up bugs. We have some follow-up changes coming such as adding a mach target, replacing –enable-gtest by –enable-tests and adding gtests to tinderbox. Everything is now ready for developers to start adding their own unit tests to libxul.
All the unit tests will be linked within libxul. This means that you don’t have to export any symbols you intend on testing. See Bug 767231 for the pros and cons of this solution. The summary is that unit tests will run against a different libxul library (libxul+unittest) than the one we will ship (libxul only) at the benefit of having access to all the symbols. Unit tests will not be shipped in a normal release build.
To run GTest build with ‘–enable-gtest’ and simply add the -unittest option when running firefox. To add an unit test create a test .cpp file, declare it to the makefile ‘GTEST_CPPSRCS = TestFoo.cpp’ and you’re done.
For more details see the up-to-date documentation: https://developer.mozilla.org/en-US/docs/GTest
Does your Firefox take a long time to shutdown? Do you get “Firefox is already running” messages when restarting? Well the Firefox Performance team would like to fix that, so please keep reading!
The Gecko Profiler extension now has a new feature called the (Automatic) ‘Performance Reporter’. If you opt into this feature, the profiler will watch your browser for any performance hiccups and will automatically send a detailed bug report for the Performance team to fix! Currently, this Performance Reporter feature monitors only your browser’s shutdown behavior and only sends us a report if shutdown takes longer then 1.5 seconds, but we would like to extend it to cover all aspects of Firefox performance. The reporter works in the background and does not interfere with your use of the browser.
The performance reports contain the URLs of the tabs you have open and are uploaded publicly for processing, so if you are not comfortable with communicating this information, do not enable this feature — we understand! We have taken precautions to never record anything coming from a private browsing window. Also, please note that the Performance Reporter is not related to Firefox’s Telemetry or Health Report features which never send any sensitive information such as URLs. The Performance Reporter is different — it collects very rich data so we can get a complete picture of any performance problem.
How do you turn this on? Make sure you’re running the latest version of the Gecko Profiler which should read as v1.11.17 or later. If I have not scared you away great, turning on the Performance Reporter is as simple as flipping ‘profiler.performanceReporter’ in about:config.
We’ve previously added video profiles in mobile and run them daily with eideticker. Here’s a proof a concept for doing the same thing for tracking page load on desktop.
This works by tagging frames and CPU samples with a frame number. During the analysis we use this information to correlate the video stream with the CPU samples. This lets us take something like a page load, slow it down and watch what we’re executing at each frame.
Take a look at this profile and follow along. I’ll only describe 4 interesting frames but feel free to look at the rest. When seeking with the video the corresponding region will be highlighted in the profile timeline. You can then click on samples in that timeline and they will be selected and appear as green:
- Seek to 4 seconds where the page is requested. This will continue to 5.5 seconds. During this we see a little network activity and a bit of work compositing to update the throbber. This is no surprise since my WiFi signal was poor.
- Seek to 5.5 seconds where the page starts to appear on screen. Lets look closer at the first frame in order.
- 20 ms compiling JS
- 8 ms executing the JS from the page
- 5 ms is spent in Adblock
- 11 ms processing styles
- 37 ms reflowing the page, 16 ms of which is doing main thread IO loading fonts when calling ‘CGFontCreateWithFontName’.
- Negligible time building the display list (profiler sampling rate too high)
- 19 ms drawing and compositing
- Seek to 5.9 seconds where we are waiting on the plugin to load. The plugin takes 200ms to load. This means we miss several frames.
- Seek to about 7.3 seconds. During this frame the plugin stream is created. This adds another 100 ms delay.
Video Profile of Page Load
My goal is to start making video capture features into the profiler add-on to make these profiles easier to capture.
I made my first small WebGL app that fetches a star catalog and displays stars within 25 parsec (80 lightyear) using WebGL+Three.JS. I also created a second view that will only show named star and will try to fetch their Wikipedia page on mouse over.
I didn’t trim the catalog so be prepared to wait for 8mb of text to load :).
Try it out:
View 1: Stars within 80 light years
View 2: Named stars only
This demo is missing a lot of optimization so it shouldn’t be used for benchmarking.
I also unfortunately didn’t get around to calculating and displaying the relative size of each star.
I posted a change to TryChooser that will fetch the build queue and display it when selecting tests. Do your part by avoiding platforms with large queues if possible to get your results faster and help reduce contention.
TryChooser Load: Avoid platforms with high numbers.
With the landing of bug 799640, the profiler add-on can now profile shutdown. I’ve created a dashboard that summarizes data from 10 of my shutdown profiles. Take a look at the dashboard here. You will find the shutdown profiles in the second section half way down the page. You’ll see 10 profiles under total or per function, clicking on any of them will open them in the preview and will filter by the function. Shutdown is at the end of the profile so I recommend focusing from the first pink shutdown marker and onward. You’ll see the following shutdown markers:
- Shutdown start: A shutdown has been requested.
- Shutdown early: Where we hope to call exit(0) eventually. Nearly everything after will not run with a few exceptions that will be moved before this point.
- Shutdown xpcom: Where we hope to call exit(0) soon.
What are we doing during shutdown? Here’s some trivia about my shutdowns:
- Takes from 1,000ms to 2,700ms making shutdown highly variable. As expected runs with higher uptime had slower shutdowns.
- Most of the shutdown time is spent doing GC/CC. This is because we persist data on destructors forcing us to clean up. This is getting fixed by exit(0) in bug 662444.
- Placing exit(0) at ‘Shutdown early’ would save between 1/3 to 2/3 of the shutdown time depending on the instance.
- Our shutdown is blocked by plugins because they may also need to persist data. Sadly this has to happen synchronously on the main thread and takes a consistent 90ms for me. We’re discussing options in bug 818265.
- Pages such as gmail.com block shutdown by running scripts on ‘page hide’ which is called on shutdown. This is unbounded but in my case was about 100ms.
- Startup and shutdown performance bugs are being tracked in bug 810156.
- Shutting down with less the 10 seconds of uptime will cause the startup cache to be saved on shutdown bug 816656.
After I’ve had time to study this data more I’m hoping gather performance data on other people’s profile to give a better sample of shutdown times since my Firefox profile is simple and I don’t stockpile 100s of tabs in my session like most do.