413904 - Sunbird 0.8pre is 4x slower in js-startup than 0.7

Status: VERIFIED INVALID

(Calendar :: General, defect)

Description

[Joey Minta]

I saw the recent post about performance improvements on Planet and thought I'd see what the actual numbers looked like.  They were... not good.  Maybe there's something wrong with my test method, so here's what I did.

1.) Download 0.7 release and 0.8pre nightly builds.  For each build, then:
2.) Unzip calendar.jar
3.) Edit content/calendar/calendar.js adding the following 3 lines to the end of calendarInit()
  var now = Date.now();
  var then = getCalendarManager().wrappedJSObject._time;
  Components.utils.reportError(now-then);
4.) Rezip calendar.jar
5.) Edit components/calItemModule.js adding the following line to the very top/global scope:
  var timer = Date.now();
6.) Edit js/calCalendarManager.js adding the following line to the calCalendarManager() constructor:
  this.wrappedJSObject._time = timer;
7.) Launch each application with a clean profile. *See note
8.) Launch each application 5 more times.  Record data in Error Console.

The goal of this test is to capture as much of startup-time as possible.  Since these were pre-made builds, hacking C++ code to get an earlier startup-time mark was not possible.  Instead, adding the line to the global scope of calItemModule ensures it is the first javascript line run.  Then, assuming the end of calendarInit() marks the end of startup, we have a reasonable measure of startup time.

Actual results:
Sunbird 0.7: 176,173,182,174,173
Sunbird 0.8pre: 776,762,761,776,785

Don't ask me where all that time is lost, but these were clean profiles, so assume it wasn't too much involving drawing views or reading calendar files.  Also, since the first-run was discarded, it likely wasn't setting up tables/prefs either.

*Note: The first-run time is inaccurate, because the migration window blocks the rest of the load, meaning that the time will change depending on how quickly you hit "Cancel" on the migrator.

This is a pretty dramatic performance loss, especially for a release which has "better performance" as a goal.  I'm guessing it should block until startup is reduced to a number more comparable to 0.7 (a release already criticized for perf).

Comment 1

[Stefan Sitter [:ssitter]]

But what does this mean? Or what is visible to the user?

I used a stop watch to measure the time from clicking the Sunbird icon until Sunbird was started up and showed the month view with my events. I used my real profile for testing to get some real timing values. I repeated the measurement a dozen times and calculated the average startup time.

average startup time using Sunbird 0.7:    9.2 sec
average startup time using Sunbird 0.8pre: 7.1 sec

Yes, it is still slow but compared to 0.7 the startup time decreased by 20% for me.

Comment 2

[Joey Minta]

(In reply to comment #1)
> But what does this mean? Or what is visible to the user?

What that says to me is that while the underlying Gecko got faster, the calendar portion did not.  Unless there is some non-js portion of calendar that had significant performance gains, I don't think the win you're seeing is attributable to calendar code.  In particular, this means that for Lightning (I may try to run the same test there later) which will have the same gecko between 0.7 and 0.8, the impact on Thunderbird would be the direct 400% slowdown shown in startup.

Comment 3

[Joey Minta]

Ok, I re-ran the tests with Lightning, and the results there are a bit less disheartening.  On my computer, it's showing a slowdown of 50ms (again with a blank profile)

0.7: 1289, 1263, 1292, 1297, 1263
0.8pre: 1325, 1341, 1331, 1322, 1333

Note that lightning does not have a central load-function, so after making the same changes to calCalendarManager.js and calItemModule.js, I added the following lines to the top of messenger-overlay-sidebar.js:

  function timer() {
    function innerTimer() {
      var now = Date.now();
      var then = getCalendarManager().wrappedJSObject._time;
      Components.utils.reportError(now-then);
    }
    setTimeout(innerTimer, 0);
  }
  window.addEventListener("load", timer, false);

The setTimeout line will obviously raise some eyebrows.  The intent here is that the callback to innerTimer should not fire until all "load" handlers have finished.  The setTimeout call attempts to ensure that this is so.  Note of course that setTimeout actually has a minimum resolution of 10ms, but since this was held constant across the tests, it should not have had an impact.

Comment 4

[Simon Paquet [:sipaq]]

(In reply to comment #2)
> What that says to me is that while the underlying Gecko got faster, the
> calendar portion did not. Unless there is some non-js portion of calendar 
> that had significant performance gains, I don't think the win you're seeing 
> is attributable to calendar code.

Joey, 0.8pre is developed on the MOZILLA_1_8_BRANCH as was 0.7. So I don't think that the underlying Gecko core is the reason for the differences and has been getting way faster between the end of October 2007 and now.

Comment 5

[Simon Paquet [:sipaq]]

Plussing for investigation.

Comment 6

[Philipp Kewisch [:Fallen][☁️📆]]

Which build did you test first? If 0.8pre, did you restart your machine between tests? I believe the OS caches some things when a program is started, so the speedup might come from the OS cache.

Comment 7

[Joey Minta]

Each build was started once before the test, and then the first runs were thrown out, since the fastload and cache files were being built then. 0.7 was tested first.

Comment 8

[Daniel Boelzle [:dbo]]

IMHO a 3-4% performance decrease (per comment #3) doesn't warrant blocking status.

Comment 9

[Joey Minta]

(In reply to comment #8)
First, it's not 3-4% for Sunbird, is 400%.  Does Sunbird not matter? Second, how is "better performance" compatible with "slower startup" no matter the percentage?

Comment 10

[Andreas Treumann]

Here is my test result 'Startup Performance Sunbird 0.7 against 0.8pre':

two locale calendars:

0.7 : 4,55 | 4,28 | 5,14 | 4,42 | 4,36 | => average 4,55 sec.
0.8 : 3,93 | 5,11 | 4,87 | 4,84 | 4,52 | => average 4,65 sec.

two locale calendars, one remote ics-calendar (http://ical.mac.com/ebony.ivory/Musicians'%20Birthdays.ics )

0.7 : 21,17 | 19,50 | 19,93 | 20,34 | 19,63 | => average 20,11 sec.
0.8 : 14,58 | 16,54 | 15,00 | 14,45 | 14,45 | => average 15,00 sec.

two locale calendar, one remote ics-calendar (http://ical.mac.com/ebony.ivory/Musicians'%20Birthdays.ics ), one 
WCAP-calendar

0.7 : 20,74 | 20.07 | 19,95 | 20,15 | 20,12 | => average 20,21 sec.
0.8 : 14,61 | 14,42 | 15,11 | 15,23 | 14,70 | => average 14,81 sec.

This test results fits with comment #1. I could not see a performance issue in Sunbird 0.8pre.

Comment 11

[Daniel Boelzle [:dbo]]

Just to add: Andreas has run the tests on MacOS X 10.5 (Leopard).

Comment 12

[Joey Minta]

(In reply to comment #10)
> Here is my test result 'Startup Performance Sunbird 0.7 against 0.8pre':
What specifically were you timing here?  If people have a way to time the whole startup of the app, I'd be happy to make my own reports.  My method in comment #0 was simply the best way I knew to approximate that timing.  Can you share your method?

Comment 13

[Andreas Treumann]

My method was simple: start sunbird via double click, wait, stop when 
the calendar week view is completely loaded. This is the experience of a 
common user when he starts an application.

Comment 14

[Joey Minta]

Right, but how did you do the timing?  Maybe I just don't have the reaction time of ssitter who can use a stopwatch manually...

Comment 15

[Andreas Treumann]

From my point of view the reaction time is insignificant because this time should be in all of my test runs be nearly the same. To reduce this I run this test 5 times to get an average time.

Comment 16

[Michiel van Leeuwen (email: mvl+moz@)]

I'm working on a test based on how startup time of firefox (Ts) is measured. It works by passing in the current time as command-line parameter. The end-time is determined by an onload of the view. The difference is the startup-time. I think that's basically what Andreas time, but without the human reaction time.
Most of that already works as extension. The only patch that's needed is the emit the onload from the views. But that change is small, and can be applied to a 0.7 build. I'm trying to make it work with talos, so the test can be run automatically.

Comment 17

[Joey Minta]

That would be really really awesome.

Comment 18

[Michiel van Leeuwen (email: mvl+moz@)]

Attachment: performance test extension

I also ran some test. I used an extension that added some command line options, so I could really measure the time from startup to when the views are loaded. See the attached extension. (I need to clean it up a bit, add license headers etc) If you want to use it, you need to edit calendar-multiday-view.xml and calendar-month-view.xml. Add 
      this.calView.fireEvent('viewload', aOperationType);
to the top of the onOperationComplete function.

My results:
sunbird 0.7:    1156 1226 1150 1151 1163 1165 ms
current branch: 1156 1173 1299 1181 1149 1162 ms

Not really any difference...

(btw, I managed to use talos for this. I needed to add a few small changes. Contact me if you want to have them. I hope to be able to get some real testboxes set up one day, and add a bunch of extra tests)

Comment 19

[Joey Minta]

Wow, that's really sweet.  Gonna mark this bug as invalid based on mvl's data.