rstrong's blog

in search of ponies

Status update – week of 1/29

January 31st, 2010

Progress:


Future targets:



No Comments »

Status update – week of 1/15

January 15th, 2010

Progress:


Future targets:



No Comments »

Status update – week of 1/8

January 8th, 2010

Progress:


Future targets:



No Comments »

Firefox JavaScript component startup costs

December 23rd, 2009

I’ve spent some time profiling the startup costs for JavaScript components from the first app-startup notification through the last final-ui-startup notification. I’ve limited the data to just these notifications for the time being in order to keep the focus specifically on this subset of startup cost to make the analysis easier. All times are in milliseconds and the profiling was done on WinCE Firefox trunk using a Tegra device. The patches in Bug 507012 were used and as can be seen the noise is pretty darn small. Where possible I have calculated the difference between the start and end time for each component (this isn’t immediately obvious from the log files) so the data would include at least some of the native code cost for the component during startup. This additional cost is readily apparent in the tables at the end of this post where fuelApplication.js is removed entirely from startup.

Note: get_PB_Enabled is short for PBS_get_privateBrowsingEnabled in nsPrivateBrowsingService.js.

Samples: 50

stage file function avg stdev min max
start to final     3946.148 62.610 (1.59%) 3832.055 4087.264
app-startup     927.774 8.117 (0.87%) 911.413 946.115
app-startup fuelApplication.js JS_Execute 632.945 7.690 (1.21%) 617.986 655.014
app-startup fuelApplication.js init|observe 22.706 0.301 (1.33%) 22.368 23.980
app-startup nsSessionStartup.js JS_Execute 27.703 0.304 (1.10%) 27.271 28.404
app-startup nsSessionStartup.js init|observe 12.801 0.137 (1.07%) 12.645 13.180
app-startup nsBrowserGlue.js JS_Execute 48.739 0.527 (1.08%) 45.564 49.544
app-startup nsBrowserGlue.js init|observe 22.068 0.129 (0.58%) 21.931 22.386
app-startup nsPrivateBrowsingService.js JS_Execute 30.141 0.306 (1.01%) 29.725 31.694
app-startup nsPrivateBrowsingService.js init|observe 21.593 0.177 (0.82%) 21.341 22.277
app-startup WebContentConverter.js JS_Execute 33.150 0.225 (0.68%) 32.904 34.148
app-startup WebContentConverter.js init|observe 9.549 0.073 (0.76%) 9.444 9.741
app-startup nsTryToClose.js JS_Execute 12.994 0.386 (2.97%) 12.587 14.098
app-startup nsTryToClose.js init|observe 10.511 0.247 (2.35%) 10.164 11.232
profile-after-change     343.994 3.557 (1.03%) 337.407 352.034
profile-after-change nsPrivateBrowsingService.js observe 8.906 0.278 (3.12%) 8.232 9.834
profile-after-change nsExtensionManager.js JS_Execute 192.271 3.356 (1.75%) 186.200 199.659
profile-after-change nsExtensionManager.js init|observe 86.652 0.493 (0.57%) 84.153 84.153
profile-after-change nsUpdateTimerManager.js JS_Execute 19.618 0.099 (0.50%) 19.376 19.832
profile-after-change nsUpdateTimerManager.js init|observe 11.913 0.100 (0.84%) 11.779 12.122
profile-after-change nsUpdateServiceStub.js JS_Execute 9.062 0.083 (0.92%) 8.877 9.265
profile-after-change nsUpdateServiceStub.js init 9.599 0.198 (2.06%) 9.396 10.240
command-line-startup     3.953 0.079 (2.00%) 3.866 4.108
command-line-startup nsPrivateBrowsingService.js observe 3.953 0.079 (2.00%) 3.866 4.108
called-from-native nsPrivateBrowsingService.js get_PB_Enabled 2.130 0.085 (4.01%) 2.059 2.450
called-from-native nsExtensionManager.js EM_start 201.015 2.805 (1.40%) 196.609 208.310
final-ui-startup     183.553 0.932 (0.51%) 181.029 186.338
final-ui-startup nsBrowserGlue.js observe 167.908 0.907 (0.54%) 165.127 170.474
final-ui-startup nsSessionStartup.js observe 13.533 0.179 (1.32%) 13.235 13.995
final-ui-startup fuelApplication.js observe 1.637 0.110 (6.73%) 1.564 1.873

 
 
Totals for each component using their averages from the previous table.

Samples: 50

Component JS_Execute CallHooks Total
fuelApplication.js 632.945 24.343 657.288
nsExtensionManager.js 192.271 287.667 479.937
nsBrowserGlue.js 48.739 189.976 238.715
nsPrivateBrowsingService.js 30.141 36.582 66.723
nsSessionStartup.js 27.703 26.334 54.037
WebContentConverter.js 33.150 9.549 42.698
nsUpdateTimerManager.js 19.618 11.913 31.531
nsTryToClose.js 12.994 10.511 23.505
nsUpdateServiceStub.js 9.062 9.599 18.660

 
 
One thing that stands out is that fuelApplication.js appears to be paying a penalty for being the first JavaScript component to load. To verify this I made nsSessionStartup.js load first, fuelApplication.js load second, and analyzed the new data. The results showed that the load first penalty is ≈ 558ms for JS_Execute and ≈ 10ms for the first CallHook.

Totals for each component using their averages with nsSessionStartup.js loading first and fuelApplication.js loading second (complete table not shown).

Samples: 50

Component JS_Execute CallHooks Total
nsSessionStartup.js 584.927 37.141 622.067
nsExtensionManager.js 192.704 288.571 481.275
nsBrowserGlue.js 48.255 189.883 238.138
fuelApplication.js 74.777 15.408 90.185
nsPrivateBrowsingService.js 30.115 36.482 66.597
WebContentConverter.js 33.068 9.534 42.601
nsUpdateTimerManager.js 19.615 11.916 31.530
nsTryToClose.js 12.987 10.508 23.495
nsUpdateServiceStub.js 8.949 9.653 18.602

 
 
There are a couple of things that can be done to the nsExtensionManager.js component that I’ll write about later. Besides optimizing a couple of these components I think that the fuelApplication.js component should either be re-written as a JavaScript module or be removed entirely. With its removal from the startup path startup time is reduced by ≈ 140ms on WinCE Firefox trunk with a Tegra device as can be seen below. I suspect that this would also reduce startup on a few of the Firefox desktop platforms by ≈ 1%.

Filed: Bug 536504 [Firefox] – Remove fuelApplications.js from the startup path [All]

Samples: 30

stage file function avg stdev min max
start to final     3806.027 54.004 (1.42%) 3673.833 3919.366
app-startup     824.938 9.636 (1.17%) 807.022 844.464
app-startup nsSessionStartup.js JS_Execute 569.328 6.921 (1.22%) 554.889 580.804
app-startup nsSessionStartup.js init|observe 23.529 1.419 (6.03%) 21.495 26.296
app-startup nsBrowserGlue.js JS_Execute 52.306 3.796 (7.26%) 36.339 59.105
app-startup nsBrowserGlue.js init|observe 22.714 0.112 (0.50%) 22.513 22.945
app-startup nsPrivateBrowsingService.js JS_Execute 28.945 0.163 (0.56%) 28.527 29.397
app-startup nsPrivateBrowsingService.js init|observe 20.176 0.110 (0.55%) 19.980 20.384
app-startup WebContentConverter.js JS_Execute 35.192 0.173 (0.49%) 34.916 35.591
app-startup WebContentConverter.js init|observe 9.532 0.128 (1.34%) 9.305 9.968
app-startup nsTryToClose.js JS_Execute 13.500 0.560 (4.14%) 13.083 14.826
app-startup nsTryToClose.js init|observe 9.889 0.317 (3.20%) 9.559 10.702
profile-after-change     343.520 5.753 (1.67%) 330.411 360.803
profile-after-change nsPrivateBrowsingService.js observe 5.880 0.442 (7.51%) 4.748 6.569
profile-after-change nsExtensionManager.js JS_Execute 196.433 5.820 (2.96%) 184.414 215.039
profile-after-change nsExtensionManager.js init|observe 86.338 0.264 (0.31%) 85.751 86.854
profile-after-change nsUpdateTimerManager.js JS_Execute 19.623 0.094 (0.48%) 19.428 19.792
profile-after-change nsUpdateTimerManager.js init|observe 11.814 0.111 (0.94%) 11.701 11.701
profile-after-change nsUpdateServiceStub.js JS_Execute 7.826 0.083 (1.06%) 7.608 8.059
profile-after-change nsUpdateServiceStub.js init 9.714 0.080 (0.82%) 9.588 9.882
command-line-startup     4.940 0.073 (1.48%) 4.837 5.111
command-line-startup nsPrivateBrowsingService.js observe 4.940 0.073 (1.48%) 4.837 5.111
called-from-native nsPrivateBrowsingService.js get_PB_Enabled 2.137 0.103 (4.81%) 2.054 2.390
called-from-native nsExtensionManager.js EM_start 197.268 2.809 (1.42%) 193.497 204.272
final-ui-startup     177.882 0.716 (0.40%) 177.263 180.097
final-ui-startup nsBrowserGlue.js observe 164.155 0.631 (0.38%) 163.518 166.598
final-ui-startup nsSessionStartup.js observe 13.495 0.399 (2.96%) 13.215 15.489

 
 
Totals for each component using their averages without fuelApplication.js from the previous table.

Samples: 30

Component JS_Execute CallHooks Total
nsSessionStartup.js 569.328 37.024 606.352
nsExtensionManager.js 196.433 283.605 480.038
nsBrowserGlue.js 52.306 186.869 239.174
nsPrivateBrowsingService.js 28.945 33.134 62.080
WebContentConverter.js 35.192 9.532 44.724
nsUpdateTimerManager.js 19.623 11.814 31.437
nsTryToClose.js 13.500 9.889 23.389
nsUpdateServiceStub.js 7.826 9.714 17.539

 
 
The profile logs used for this analysis include additional details including call stacks and are available for download…
profile logs


5 Comments »

status update – week of 12/18

December 18th, 2009

Progress:


Future targets:



No Comments »

I’m surprised no one…

December 17th, 2009

has blamed MS yet for this!


Comments Off

status update – week of 12/11

December 13th, 2009

Progress:


Future targets:


Over the weekend I measured time spent on trunk in JS during startup through final-ui-startup on Windows 7 using the patch in Bug 507012 and should be able to do the same on WinCE / WinMo in the near future. I haven’t include top level calls to XPCOMUtils at present due to not having the time to associate them with their respective consumers. Even without this it is still easy to see which components need some startup love.

File JS_Execute CallHooks Total
nsExtensionManager.js 5.940ms 9.598ms 15.538ms
nsBrowserGlue.js 2.520ms 9.529ms 12.049ms
fuelApplication.js 3.081ms 0.969ms 4.050ms
nsSessionStartup.js 1.072ms 1.625ms 2.697ms
nsPrivateBrowsingService.js 1.316ms 0.914ms 2.230ms
WebContentConverter.js 1.629ms 0.315ms 1.944ms
nsUpdateTimerManager.js 1.201ms 0.440ms 1.641ms
nsTryToClose.js 0.851ms 0.318ms 1.169ms
nsUpdateServiceStub.js 0.899ms 0.080ms 0.979ms
Total 18.509ms 23.788ms 42.297ms

Note: the first component to load (fuelApplication.js) paid a penalty of approximately 17.57ms in JS_Execute on my system which was subtracted from fuelApplication.js in the numbers above. The real time spent in JS_Execute for fuelApplication.js is 20.651ms.

Using the same build and the nsUpdateService.js from 3.6 beta 1 the time spent in app update during startup is ≅ 18.554ms compared to ≅ 2.62ms now for a total savings of ≅ 15.934 or ≅ 85%.

More needs to be done to improve the reporting / analysis and I’ll blog about this including the raw data after more progress has been made.

Edited to add a reply to a comment: “these small numbers on desktop represent large numbers on mobile and if we are able to find four similar savings it turns into around a 10% TS win on desktop since they add up quickly.” Also see The fastest code is the code that never runs for more background info.


3 Comments »

status update – week of 12/4

December 4th, 2009

Any week where startup time (a.k.a TS) is improved even by a small amount is a good week. On Wednesday I found a startup win (mostly noticeable on Mobile but there was a slight win reported for Ts, MED Dirty Profile decrease 0.74% on XP Firefox3.6 and Ts, MAX Dirty Profile decrease 0.53% on Linux Firefox3.6 so far) and managed to get it landed for 3.6 (thanks Mossop for the review and Beltzner for the approval)… with this kind of luck I expect to find a pony waiting for me when I get home from work today.

Progress:


Future targets:



1 Comment »

The fastest code is the code that never runs

November 29th, 2009

The really short version:


On WinCE Firefox the average time spent in application update’s JavaScript components during startup was ≅ 181 ms and after Bug 311965 landed it was ≅ 51 ms… ≅ 72% savings. This was accomplished by creating a separate component that performed the bare minimum of work during startup. This is on top of previous work that reduced application update startup time on Maemo Fennec from ≅ 200 ms to ≅ 150 ms which is ≅ 25% savings. Altogether the total improvement taking into account the earlier work on application update on WinCE Firefox is ≅ 175 ms or ≅ 77%.

The longer (though still short) version:

On mobile platforms almost all code is quite a bit more expensive than on desktops where the OS / hardware optimizes around the performance costly areas and when all of our current tools for measuring performance focus on the desktop platforms it is difficult to give the mobile platforms performance work a high priority. For me, it is a case of “out of sight, out of mind”. How should this be resolved? First and foremost we need stable performance numbers for at least one mobile platform. It would also be extremely helpful if developers had access to more detailed info regarding the time spent in each component during startup especially if it was available from the try servers. This data can be had when using the patch from Bug 470116 [Core] – Component for timing execution of js and others [Linux] but few developers have this hardware available. As I understand it Bug 480735 [Core] – Startup timeline [All] also provides this data but I can’t confirm this since I used the patch in Bug 470116 for performance measurements.

Over the years a lot of code has been bolted on to application update to provide additional functionality without taking into consideration the affect the changes would have on startup. For example, on Vista there were multiple write access checks that in some cases were for the same directory. This sounds bad but on desktops the affect was so slight that it was less than the noise factor in our performance tests so it really was negligable in the pre-mobile days. Prior to rafactoring the update service by using a stub I reviewed the existing code and optimized it as appropriate so the case where the application update component processes an update is faster too. This is the reverse of my normal approach of taking the low hanging fruit and then spending an inordinate amount of time finding the little wins. I took this approach since there are always plenty of things to fix and it would have been very easy to just keep putting off optimizing this code especially since it would have been taken out of the common startup path.

Prior to Bug 311965 landing application update only had the nsUpdateService.js file and now it has the nsUpdateService.js, nsUpdateServiceStub.js, and nsUpdateTimerManager.js files with only nsUpdateServiceStub.js and nsUpdateTimerManager.js being loaded on startup for the normal case. As a side benefit if the application is built with “ac_add_options –disable-updater” nsUpdateService.js, nsUpdateServiceStub.js, and the updater binary are not built which improves startup on Maemo Fennec by an additional ≅ 12 ms which was changed in Bug 530393 [Fennec] – Don’t build updater code for Maemo. Though having less files is important for the cold startup case having more files can drastically improve startup when the application has a fastload file and the stub file performs a small amount of work as compared to a large file that takes longer to load and evaluate.

It turns out that js_execute tends to be what hurts most during startup and there is Bug 522354 [Core] – investigate why we spend a long time js_execute()ing things [Linux] to investigate this. I hope that time spent in js_execute can be improved but this in no way negates the need to re-evaluate time spent in startup for all JavaScript components… I can’t imagine Bug 522354 being some sort of silver bullet for improving startup time and I highly suspect any work done in JavaScript components to improve startup time will still be applicable even with any improvements provided by Bug 522354 or other bugs.

When it comes to mobile disk IO is the thing most often stated when it comes to startup performance. I know disk IO on mobile has a hefty cost but it is way too easy to focus on disk IO and skim over everything else. The initial patches to improve performance for application update focused mostly on lessening disk IO and they did improve startup significantly (around 25%) but no where near as much as using a stub for the service. For example, prior to the application update refactoring I had removed the write access checks for WinCE to improve startup performance and was able to add them back with the stub while still being able to improve startup performance.

Now I try to forget about the desktop when optimizing especially for small improvements… Talos will catch regressions / improvements on the desktop but the noise in the numbers is such that it is impossible to catch small improvements. On a mobile device it is quite clear whether a change has improved or regressed startup. For example, the 131 ms improvement I measured on WinCE Firefox appeared to improve startup on desktop by a couple of ms on Talos desktop though that is well within the noise. Once again, it would be extremely helpful to developers if this information was available for mobile via the tinderboxen and the try servers.

There is still a ton of work to be done on the low hanging fruit… just take a look at the numbers from sample WinCE Firefox log. For example…
components/nsBlocklistService.js – 356 ms
components/nsExtensionManager.js – 338 ms
components/nsBrowserGlue.js – 211 ms

Thanks go out to Taras for patiently answering my questions and providing me with data as I slowly acquired a more mobile orientated mindset along with his own work to improve startup performance for everyone by improving the core of Mozilla and to dietrich for taking on making startup performance improvement a primary goal for the Firefox team.


2 Comments »

App update status – week of 11/27

November 25th, 2009

Posting early since I’ll be out the remainder of this week.

Progress:


Future targets:


Some of the significant bugs I am looking at fixing for Firefox 3.7



1 Comment »

Next Page »