Bad performance for larger .ics calendars
Simon Paquet
There have been repeated reports, that our performance for .ics
calendars has declined since 0.5. I've tried to come up and with an
explanation for this, so I tried to profile a simple app operation.
Here's what I did:
Setup:
======
Machine: Pentium M 1,7 GHz, running WinXP, 1 GB RAM
Build: Sunbird nightly (Gecko/20071206 Calendar/0.8pre)
Debugger: Venkman 0.9.87.1 [Mozilla rv:1.8.1.11pre/0]
Test calendar:
http://info.vassar.edu/calendar/calendars/campuscalendar.ics
Calendar size: 233 KB
Test setup:
===========
1. Install fresh Sunbird build
2. Install Venkman add-on
3. Restart Sunbird (Go to the month view)
4. Disable all active calendars (I only disabled an empty Home calendar)
5. Download the test calendar to your harddrive
6. Subscribe to this local .ics calendar
7. Start Venkman
8. Enable Profiling in Venkman
9. Go back to Sunbird and switch to November
10. Switch back to Venkman and export the profiling data
Results:
========
1. We lose a lot of time in the GetRange function in
calMemoryCalendar.ics and calICSCalendar.js
(7370.53 milliseconds respectively in both files)
2. There could also be room for optimization in calEvent.js and
calItemBase.js
Detailed results: (without the calls for toolkit and venkman files)
===================================================================
0 <chrome://calendar/content/calendar-view-core.xml>
calendar-view-core.xml: 100 - 250 milliseconds
Function Name: __toplevel__ (Lines 101 - 118)
Total Calls: 306 (max recurse 0)
Total Time: 200.29 (min/max/avg 0/10.02/0.65)
Time (ex. calls): 200.29 (min/max/avg 0/10.02/0.65)
--------------------------------------------------------
1 <chrome://calendar/content/calendar-view-core.xml>
calendar-view-core.xml: 10 - 25 milliseconds
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 10.02 (min/max/avg 10.02/10.02/10.02)
Time (ex. calls): 10.02 (min/max/avg 10.02/10.02/10.02)
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 10.02 (min/max/avg 10.02/10.02/10.02)
Time (ex. calls): 10.02 (min/max/avg 10.02/10.02/10.02)
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 10.01 (min/max/avg 10.01/10.01/10.01)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 10.01 (min/max/avg 10.01/10.01/10.01)
Time (ex. calls): 10.01 (min/max/avg 10.01/10.01/10.01)
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 10.01 (min/max/avg 10.01/10.01/10.01)
Time (ex. calls): 10.01 (min/max/avg 10.01/10.01/10.01)
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 10.01 (min/max/avg 10.01/10.01/10.01)
Time (ex. calls): 10.01 (min/max/avg 10.01/10.01/10.01)
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 10.01 (min/max/avg 10.01/10.01/10.01)
Time (ex. calls): 10.01 (min/max/avg 10.01/10.01/10.01)
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 10.01 (min/max/avg 10.01/10.01/10.01)
Time (ex. calls): 10.01 (min/max/avg 10.01/10.01/10.01)
calendar-view-core.xml: 0 - 0.25 milliseconds
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: onxblmouseover (Lines 327 - 331)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
----------------------------------------------------
13
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calDateTimeFormatter.js>
calDateTimeFormatter.js: 50 - 75 milliseconds
Function Name: formatTime (Lines 174 - 183)
Total Calls: 360 (max recurse 0)
Total Time: 60.08 (min/max/avg 0/10.02/0.17)
Time (ex. calls): 60.08 (min/max/avg 0/10.02/0.17)
calDateTimeFormatter.js: 10 - 25 milliseconds
Function Name: formatInterval (Lines 206 - 250)
Total Calls: 27 (max recurse 0)
Total Time: 10.01 (min/max/avg 0/10.01/0.37)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: formatDateTime (Lines 186 - 203)
Total Calls: 40 (max recurse 0)
Total Time: 10.01 (min/max/avg 0/10.01/0.25)
Time (ex. calls): 0 (min/max/avg 0/0/0)
calDateTimeFormatter.js: 0 - 0.25 milliseconds
Function Name: formatDate (Lines 116 - 131)
Total Calls: 47 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: formatDateLong (Lines 143 - 158)
Total Calls: 47 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: QueryInterface (Lines 106 - 113)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
---------------------------------------------------------
14
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calEvent.js>
calEvent.js: 1000 - 2500 milliseconds
Function Name: anonymous (Lines 89 - 98)
Total Calls: 22433 (max recurse 0)
Total Time: 1622.31 (min/max/avg 0/20.03/0.07)
Time (ex. calls): 1121.6 (min/max/avg 0/20.03/0.05)
calEvent.js: 500 - 750 milliseconds
Function Name: anonymous (Lines 252 - 254)
Total Calls: 49642 (max recurse 0)
Total Time: 550.78 (min/max/avg 0/20.03/0.01)
Time (ex. calls): 130.18 (min/max/avg 0/10.02/0)
calEvent.js: 10 - 25 milliseconds
Function Name: anonymous (Lines 257 - 282)
Total Calls: 4891 (max recurse 0)
Total Time: 20.03 (min/max/avg 0/10.02/0)
Time (ex. calls): 20.03 (min/max/avg 0/10.02/0)
calEvent.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 75 - 77)
Total Calls: 329 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 63 - 73)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-----------------------------------------------------
15
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calICSCalendar.js>
calICSCalendar.js: 5000 - 1000000 milliseconds
Function Name: anonymous (Lines 425 - 475)
Total Calls: 2 (max recurse 0)
Total Time: 7370.53 (min/max/avg 430.62/6939.91/3685.26)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 416 - 422)
Total Calls: 2 (max recurse 0)
Total Time: 7370.53 (min/max/avg 430.62/6939.91/3685.26)
Time (ex. calls): 0 (min/max/avg 0/0/0)
calICSCalendar.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 122 - 123)
Total Calls: 612 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 75 - 81)
Total Calls: 10 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 487 - 489)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-----------------------------------------------------
16
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calItemBase.js>
calItemBase.js: 500 - 750 milliseconds
Function Name: anonymous (Lines 391 - 403)
Total Calls: 53776 (max recurse 0)
Total Time: 620.89 (min/max/avg 0/20.03/0.01)
Time (ex. calls): 620.89 (min/max/avg 0/20.03/0.01)
Function Name: anonymous (Lines 60 - 68)
Total Calls: 22104 (max recurse 0)
Total Time: 500.71 (min/max/avg 0/20.03/0.02)
Time (ex. calls): 500.71 (min/max/avg 0/20.03/0.02)
calItemBase.js: 50 - 75 milliseconds
Function Name: anonymous (Lines 71 - 81)
Total Calls: 5160 (max recurse 0)
Total Time: 60.08 (min/max/avg 0/10.02/0.01)
Time (ex. calls): 10.01 (min/max/avg 0/10.01/0)
calItemBase.js: 25 - 50 milliseconds
Function Name: anonymous (Lines 92 - 94)
Total Calls: 188 (max recurse 0)
Total Time: 30.04 (min/max/avg 0/10.01/0.16)
Time (ex. calls): 0 (min/max/avg 0/0/0)
calItemBase.js: 10 - 25 milliseconds
Function Name: anonymous (Lines 83 - 85)
Total Calls: 188 (max recurse 0)
Total Time: 20.03 (min/max/avg 0/10.02/0.11)
Time (ex. calls): 10.01 (min/max/avg 0/10.01/0.05)
Function Name: anonymous (Lines 786 - 791)
Total Calls: 3979 (max recurse 0)
Total Time: 10.01 (min/max/avg 0/10.01/0)
Time (ex. calls): 10.01 (min/max/avg 0/10.01/0)
calItemBase.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 494 - 496)
Total Calls: 800 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------
17
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calMemoryCalendar.js>
calMemoryCalendar.js: 5000 - 1000000 milliseconds
Function Name: anonymous (Lines 339 - 431)
Total Calls: 2 (max recurse 0)
Total Time: 7370.53 (min/max/avg 430.62/6939.91/3685.26)
Time (ex. calls): 4526.47 (min/max/avg 140.2/4386.27/2263.24)
calMemoryCalendar.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 58 - 61)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
------------------------------------------------------
18
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calProviderBase.js>
calProviderBase.js: 0 - 0.25 milliseconds
Function Name: cPB_QueryInterface (Lines 42 - 46)
Total Calls: 10 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 59 - 61)
Total Calls: 188 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 78 - 82)
Total Calls: 4 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-----------------------------------------------------
19
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calProviderBase.js>
calProviderBase.js: 0 - 0.25 milliseconds
Function Name: cPB_QueryInterface (Lines 42 - 46)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 78 - 82)
Total Calls: 4 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
------------------------------------------------------------
20
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calUtils.js>
calUtils.js: 0 - 0.25 milliseconds
Function Name: calOperationGroup_add (Lines 1376 - 1379)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: calOperationGroup (Lines 1357 - 1368)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: calOperationGroup_notifyCompleted (Lines 1395 -
1401)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: ASSERT (Lines 772 - 782)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 1414 - 1416)
Total Calls: 5 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------
21
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calUtils.js>
calUtils.js: 0 - 0.25 milliseconds
Function Name: checkIID (Lines 652 - 654)
Total Calls: 56 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: doQueryInterface (Lines 647 - 667)
Total Calls: 20 (max recurse 1)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-----------------------------------------------------------
22
<file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calUtils.js>
calUtils.js: 250 - 500 milliseconds
Function Name: checkIfInRange (Lines 946 - 996)
Total Calls: 1216 (max recurse 0)
Total Time: 290.42 (min/max/avg 0/20.03/0.24)
Time (ex. calls): 120.17 (min/max/avg 0/20.03/0.1)
calUtils.js: 50 - 75 milliseconds
Function Name: ensureDateTime (Lines 676 - 683)
Total Calls: 4868 (max recurse 0)
Total Time: 50.07 (min/max/avg 0/10.02/0.01)
Time (ex. calls): 50.07 (min/max/avg 0/10.02/0.01)
calUtils.js: 0 - 0.25 milliseconds
Function Name: checkIID (Lines 652 - 654)
Total Calls: 3 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: doQueryInterface (Lines 647 - 667)
Total Calls: 2 (max recurse 1)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: isEvent (Lines 408 - 410)
Total Calls: 2432 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
--
Calendar l10n coordinator
Calendar Website Maintainer: http://www.mozilla.org/projects/calendar
Calendar developer blog: http://weblogs.mozillazine.org/calendar
Simon Paquet
> Results:
> ========
> 1. We lose a lot of time in the GetRange function in
> calMemoryCalendar.ics and calICSCalendar.js
> (7370.53 milliseconds respectively in both files)
> 2. There could also be room for optimization in calEvent.js and
> calItemBase.js
The bad thing is, if I had done the same thing for an .ics calendar
on a remote server (not on a local hard disk), the results would have
been even worse.
Simon Paquet
> calEvent.js: 1000 - 2500 milliseconds
> Function Name: anonymous (Lines 89 - 98)
> Total Calls: 22433 (max recurse 0)
> Total Time: 1622.31 (min/max/avg 0/20.03/0.07)
> Time (ex. calls): 1121.6 (min/max/avg 0/20.03/0.05)
Is it normal, that we hit the following code so often?
| calEvent.prototype = {
| __proto__: calItemBase.prototype,
|
| QueryInterface: function (aIID) {
| if (aIID.equals(Components.interfaces.calIEvent) ||
| aIID.equals(Components.interfaces.calIInternalShallowCopy))
| return this;
|
| if (aIID.equals(Components.interfaces.nsIClassInfo))
| return calEventClassInfo;
|
| return this.__proto__.__proto__.QueryInterface.call(this, aIID);
| },
> calEvent.js: 500 - 750 milliseconds
> Function Name: anonymous (Lines 252 - 254)
> Total Calls: 49642 (max recurse 0)
> Total Time: 550.78 (min/max/avg 0/20.03/0.01)
> Time (ex. calls): 130.18 (min/max/avg 0/10.02/0)
Here it is even worse:
| get startDate() {
| return this.getProperty("DTSTART");
| },
Should this code really be called nearly 50.000 times, just for
switching from December to November for one (large) calendar with 608
VEVENTs? That's 81.65 times per VEVENT.
> calItemBase.js: 500 - 750 milliseconds
> Function Name: anonymous (Lines 391 - 403)
> Total Calls: 53776 (max recurse 0)
> Total Time: 620.89 (min/max/avg 0/20.03/0.01)
> Time (ex. calls): 620.89 (min/max/avg 0/20.03/0.01)
Here we hit this piece of code even more often:
| getProperty: function (aName) {
| aName = aName.toUpperCase();
| try {
| return this.mProperties.getProperty(aName);
| } catch (e) {
| try {
| if (this.mIsProxy) {
| return this.mParentItem.getProperty(aName);
| }
| } catch (e) {}
|
| return null;
| }
| },
> Function Name: anonymous (Lines 60 - 68)
> Total Calls: 22104 (max recurse 0)
> Total Time: 500.71 (min/max/avg 0/20.03/0.02)
> Time (ex. calls): 500.71 (min/max/avg 0/20.03/0.02)
Same as above here. Is this necessary?
| QueryInterface: function (aIID) {
| if (!aIID.equals(Components.interfaces.nsISupports) &&
| !aIID.equals(Components.interfaces.calIItemBase))
| {
| throw Components.results.NS_ERROR_NO_INTERFACE;
| }
|
| return this;
| },
Ray Kiddy
> Hi!
>
> There have been repeated reports, that our performance for .ics
> calendars has declined since 0.5. I've tried to come up and with an
> explanation for this, so I tried to profile a simple app operation.
>
Did you confirm that the performance has declined? I do not see a
comparison with the timing for the earlier version.
Sorry if you know this already, but if you do not characterize the
performance of the previous, you may see problems which are fixable, but
are not actually the causes of the specific observed regression.
- ray
Simon Paquet
>> Hi!
>>
>> There have been repeated reports, that our performance for .ics
>> calendars has declined since 0.5. I've tried to come up and with an
>> explanation for this, so I tried to profile a simple app operation.
>
>Did you confirm that the performance has declined?
Yes, older versions are noticeably faster (still slow, but faster than
current builds).
I've provided two new profile runs from my home computer (Athlon 3200+, 1
GB RAM, WinXP) with different nightlies (20070605 and 20071206).
It's obvious from those two runs, that the older build spends most of its
time in CalEvent.js and calItemBase.js, while those two are negligible
compared to the amount of time spent in calICSCalendar.ics and
calMemoryCalendar.ics
>I do not see a comparison with the timing for the earlier version.
Here is the first profile run:
Created: Fri Dec 07 2007 21:35:27 GMT+0100
User Agent: Mozilla/5.0 (Windows NT 5.1) Gecko/20070605 Sunbird/0.5
Debugger Version: Venkman 0.9.87.1 [Mozilla rv:1.8.1.4pre/0]
=================================================================================
10 <file:/C:/sunbird/js/calDateTimeFormatter.js>
calDateTimeFormatter.js: 10 - 25 milliseconds
Function Name: formatDateTime (Lines 186 - 203)
Total Calls: 176 (max recurse 0)
Total Time: 15.63 (min/max/avg 0/15.63/0.09)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: formatDate (Lines 116 - 131)
Total Calls: 213 (max recurse 0)
Total Time: 15.63 (min/max/avg 0/15.63/0.07)
Time (ex. calls): 15.63 (min/max/avg 0/15.63/0.07)
-------------------------------------------------------------------------------
calDateTimeFormatter.js: 0 - 0.25 milliseconds
Function Name: formatTime (Lines 174 - 183)
Total Calls: 555 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: formatDateLong (Lines 143 - 158)
Total Calls: 213 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: QueryInterface (Lines 106 - 113)
Total Calls: 3 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: formatInterval (Lines 206 - 251)
Total Calls: 60 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
11 <file:/C:/sunbird/js/calEvent.js>
calEvent.js: 1000 - 2500 milliseconds
Function Name: anonymous (Lines 90 - 99)
Total Calls: 21636 (max recurse 0)
Total Time: 1203.13 (min/max/avg 0/15.63/0.06)
Time (ex. calls): 875 (min/max/avg 0/15.63/0.04)
-------------------------------------------------------------------------------
calEvent.js: 500 - 750 milliseconds
Function Name: anonymous (Lines 294 - 296)
Total Calls: 50668 (max recurse 0)
Total Time: 625 (min/max/avg 0/15.63/0.01)
Time (ex. calls): 78.13 (min/max/avg 0/15.63/0)
-------------------------------------------------------------------------------
calEvent.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 76 - 78)
Total Calls: 525 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 64 - 74)
Total Calls: 3 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
12 <file:/C:/sunbird/js/calItemBase.js>
calItemBase.js: 500 - 750 milliseconds
Function Name: anonymous (Lines 354 - 366)
Total Calls: 65070 (max recurse 0)
Total Time: 687.5 (min/max/avg 0/15.63/0.01)
Time (ex. calls): 687.5 (min/max/avg 0/15.63/0.01)
-------------------------------------------------------------------------------
calItemBase.js: 250 - 500 milliseconds
Function Name: anonymous (Lines 66 - 74)
Total Calls: 21111 (max recurse 0)
Total Time: 328.13 (min/max/avg 0/15.63/0.02)
Time (ex. calls): 328.13 (min/max/avg 0/15.63/0.02)
-------------------------------------------------------------------------------
calItemBase.js: 100 - 250 milliseconds
Function Name: anonymous (Lines 750 - 755)
Total Calls: 13890 (max recurse 0)
Total Time: 125 (min/max/avg 0/15.63/0.01)
Time (ex. calls): 15.63 (min/max/avg 0/15.63/0)
-------------------------------------------------------------------------------
calItemBase.js: 25 - 50 milliseconds
Function Name: anonymous (Lines 165 - 170)
Total Calls: 2421 (max recurse 0)
Total Time: 46.88 (min/max/avg 0/15.63/0.02)
Time (ex. calls): 31.25 (min/max/avg 0/15.63/0.01)
-------------------------------------------------------------------------------
calItemBase.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 457 - 459)
Total Calls: 610 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
>Sorry if you know this already, but if you do not characterize the
>performance of the previous, you may see problems which are fixable, but
>are not actually the causes of the specific observed regression.
Correct.
Here are the relevant numbers for yesterday's Sunbird nightly (due to a
bug, you can't install add-ons in today's nightly):
Created: Fri Dec 07 2007 21:41:10 GMT+0100
User Agent: Mozilla/5.0 (Windows XP) Gecko/20071206 Calendar/0.8pre
Debugger Version: Venkman 0.9.87.1 [Mozilla rv:1.8.1.11pre/0]
=================================================================================
10 <file:/C:/sunbird/js/calCalendarManager.js>
calCalendarManager.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 95 - 107)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 544 - 560)
Total Calls: 4 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
11 <file:/C:/sunbird/js/calDateTimeFormatter.js>
calDateTimeFormatter.js: 10 - 25 milliseconds
Function Name: formatTime (Lines 174 - 183)
Total Calls: 433 (max recurse 0)
Total Time: 15.63 (min/max/avg 0/15.63/0.04)
Time (ex. calls): 15.63 (min/max/avg 0/15.63/0.04)
-------------------------------------------------------------------------------
calDateTimeFormatter.js: 0 - 0.25 milliseconds
Function Name: formatDate (Lines 116 - 131)
Total Calls: 117 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: formatDateLong (Lines 143 - 158)
Total Calls: 117 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: formatDateTime (Lines 186 - 203)
Total Calls: 106 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: QueryInterface (Lines 106 - 113)
Total Calls: 3 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: formatInterval (Lines 206 - 250)
Total Calls: 20 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
12 <file:/C:/sunbird/js/calEvent.js>
calEvent.js: 1000 - 2500 milliseconds
Function Name: anonymous (Lines 89 - 98)
Total Calls: 22895 (max recurse 0)
Total Time: 1265.63 (min/max/avg 0/15.63/0.06)
Time (ex. calls): 859.38 (min/max/avg 0/15.63/0.04)
-------------------------------------------------------------------------------
calEvent.js: 500 - 750 milliseconds
Function Name: anonymous (Lines 252 - 254)
Total Calls: 49650 (max recurse 0)
Total Time: 531.25 (min/max/avg 0/15.63/0.01)
Time (ex. calls): 93.75 (min/max/avg 0/15.63/0)
-------------------------------------------------------------------------------
calEvent.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 75 - 77)
Total Calls: 588 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 63 - 73)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 257 - 282)
Total Calls: 4934 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
13 <file:/C:/sunbird/js/calICSCalendar.js>
calICSCalendar.js: 5000 - 1000000 milliseconds
Function Name: anonymous (Lines 425 - 475)
Total Calls: 2 (max recurse 0)
Total Time: 5843.75 (min/max/avg 578.13/5265.63/2921.88)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 416 - 422)
Total Calls: 2 (max recurse 0)
Total Time: 5843.75 (min/max/avg 578.13/5265.63/2921.88)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
calICSCalendar.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 122 - 123)
Total Calls: 616 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 75 - 81)
Total Calls: 15 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 487 - 489)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
14 <file:/C:/sunbird/js/calItemBase.js>
calItemBase.js: 500 - 750 milliseconds
Function Name: anonymous (Lines 391 - 403)
Total Calls: 53819 (max recurse 0)
Total Time: 546.88 (min/max/avg 0/15.63/0.01)
Time (ex. calls): 546.88 (min/max/avg 0/15.63/0.01)
-------------------------------------------------------------------------------
calItemBase.js: 250 - 500 milliseconds
Function Name: anonymous (Lines 60 - 68)
Total Calls: 22307 (max recurse 0)
Total Time: 406.25 (min/max/avg 0/15.63/0.02)
Time (ex. calls): 406.25 (min/max/avg 0/15.63/0.02)
-------------------------------------------------------------------------------
calItemBase.js: 25 - 50 milliseconds
Function Name: anonymous (Lines 71 - 81)
Total Calls: 5147 (max recurse 0)
Total Time: 31.25 (min/max/avg 0/15.63/0.01)
Time (ex. calls): 15.63 (min/max/avg 0/15.63/0)
Function Name: anonymous (Lines 786 - 791)
Total Calls: 4005 (max recurse 0)
Total Time: 31.25 (min/max/avg 0/15.63/0.01)
Time (ex. calls): 15.63 (min/max/avg 0/15.63/0)
-------------------------------------------------------------------------------
calItemBase.js: 10 - 25 milliseconds
Function Name: anonymous (Lines 92 - 94)
Total Calls: 187 (max recurse 0)
Total Time: 15.63 (min/max/avg 0/15.63/0.08)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
calItemBase.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 494 - 496)
Total Calls: 797 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 83 - 85)
Total Calls: 187 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
15 <file:/C:/sunbird/js/calMemoryCalendar.js>
calMemoryCalendar.js: 5000 - 1000000 milliseconds
Function Name: anonymous (Lines 339 - 431)
Total Calls: 2 (max recurse 0)
Total Time: 5843.75 (min/max/avg 578.13/5265.63/2921.88)
Time (ex. calls): 3625 (min/max/avg 375/3250/1812.5)
-------------------------------------------------------------------------------
calMemoryCalendar.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 58 - 61)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
16 <file:/C:/sunbird/js/calProviderBase.js>
calProviderBase.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 70 - 72)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 59 - 61)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 96 - 98)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: cPB_QueryInterface (Lines 42 - 46)
Total Calls: 3 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: cPB_getProperty (Lines 123 - 130)
Total Calls: 3 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
17 <file:/C:/sunbird/js/calProviderBase.js>
calProviderBase.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 70 - 72)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 59 - 61)
Total Calls: 189 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 78 - 82)
Total Calls: 4 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 96 - 98)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: cPB_QueryInterface (Lines 42 - 46)
Total Calls: 15 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: cPB_getProperty (Lines 123 - 130)
Total Calls: 3 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
18 <file:/C:/sunbird/js/calProviderBase.js>
calProviderBase.js: 0 - 0.25 milliseconds
Function Name: cPB_QueryInterface (Lines 42 - 46)
Total Calls: 1 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 78 - 82)
Total Calls: 4 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
19 <file:/C:/sunbird/js/calStorageCalendar.js>
calStorageCalendar.js: 0 - 0.25 milliseconds
Function Name: anonymous (Lines 221 - 224)
Total Calls: 3 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 274 - 276)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
20 <file:/C:/sunbird/js/calUtils.js>
calUtils.js: 0 - 0.25 milliseconds
Function Name: calOperationGroup_add (Lines 1376 - 1379)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: calOperationGroup (Lines 1357 - 1368)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: calOperationGroup_notifyCompleted (Lines 1395 - 1401)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 1414 - 1416)
Total Calls: 5 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: getCalendarManager (Lines 83 - 89)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: checkIID (Lines 652 - 654)
Total Calls: 7 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: ASSERT (Lines 772 - 782)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: doQueryInterface (Lines 647 - 667)
Total Calls: 6 (max recurse 1)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
21 <file:/C:/sunbird/js/calUtils.js>
calUtils.js: 0 - 0.25 milliseconds
Function Name: getCalendarManager (Lines 83 - 89)
Total Calls: 2 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: checkIID (Lines 652 - 654)
Total Calls: 84 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: doQueryInterface (Lines 647 - 667)
Total Calls: 30 (max recurse 1)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
-------------------------------------------------------------------------------
22 <file:/C:/sunbird/js/calUtils.js>
calUtils.js: 100 - 250 milliseconds
Function Name: checkIfInRange (Lines 946 - 996)
Total Calls: 1224 (max recurse 0)
Total Time: 203.13 (min/max/avg 0/15.63/0.17)
Time (ex. calls): 109.38 (min/max/avg 0/15.63/0.09)
-------------------------------------------------------------------------------
calUtils.js: 10 - 25 milliseconds
Function Name: ensureDateTime (Lines 676 - 683)
Total Calls: 4900 (max recurse 0)
Total Time: 15.63 (min/max/avg 0/15.63/0)
Time (ex. calls): 15.63 (min/max/avg 0/15.63/0)
Function Name: isEvent (Lines 408 - 410)
Total Calls: 2448 (max recurse 0)
Total Time: 15.63 (min/max/avg 0/15.63/0.01)
Time (ex. calls): 15.63 (min/max/avg 0/15.63/0.01)
-------------------------------------------------------------------------------
calUtils.js: 0 - 0.25 milliseconds
Function Name: checkIID (Lines 652 - 654)
Total Calls: 3 (max recurse 0)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: doQueryInterface (Lines 647 - 667)
Total Calls: 2 (max recurse 1)
Total Time: 0 (min/max/avg 0/0/0)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Simon
Joey Minta
reason for table-summaries of the perf data.
On Dec 7, 2007 5:00 PM, Joey Minta <jmint...@gmail.com> wrote:
> Simon asked me to comment on this, so here are a few first-glance
> comments:
>
> (1) These numbers don't seem to show the full profile data. Specifically,
> there's no accurate data demonstrating whether the regression is on the
> front-end or backend. The long getItems times for memory and storage will
> include times for callbacks to the UI for painting. Things like the
> war-on-boxes and the revised look of the event-boxes could be impacting time
> here. To test this, comment out the onGetResult calls within
> calMemoryCalendar.js (line 419 on trunk) and re-run the profiler. NOTE:
> No events will display as a result. Instead you will be measuring pure
> provider performance. Depending on the new results, this will tell you
> whether to look for a regression in the xbl bindings or in the providers.
>
> (2) If getProperty("DTSTART") is showing up as significant in profilers,
> one might consider caching the returned value, since we have documented and
> known performance issues with the property bag. Note that this would not be
> a regression, but rather an optimization that would improve times in both
> builds. Specifically,
> _startDate: null,
> get startDate() {
> if (!this._startDate)
> this._startDate = this.getProperty("DTSTART");
> return this._startDate;
> },
>
> You would also need to add a | this._startDate = null; | line to the
> startDate setter, and perhaps to the constructor.
>
> (3) It would be much more helpful if you could post a summary chart for
> side-by-side comparison of the trunk and 0.5 numbers, by file/function and
> listing simply Venkman's "Total time" field. The long list of functions is
> difficult to analyze in a newsgroup format.
>
> -Joey
Simon Paquet
>There have been repeated reports, that our performance for .ics
>calendars has declined since 0.5. I've tried to come up and with an
>explanation for this, so I tried to profile a simple app operation.
I've done another profile run, this time for a simple reload operation of
a local .ics calendar file.
Here's what I did:
Setup:
======
Machine: Athlon 3200+, running WinXP, 1 GB RAM
Build: Sunbird nightly (Gecko/20071206 Calendar/0.8pre)
Sunbird nightly (Gecko/20070605 Calendar/0.5)
Debugger: Venkman 0.9.87.1 [Mozilla rv:1.8.1.11pre/0]
Calendar: http://info.vassar.edu/calendar/calendars/campuscalendar.ics
(saved locally on my harddrive)
Size: 233 KB
Test setup:
===========
1. Install fresh Sunbird build
2. Add reload button to your toolbar
3. Install Venkman add-on
4. Restart Sunbird (Go to the month view)
5. Disable all active calendars (I only disabled an empty Home calendar)
6. Download the test calendar to your harddrive
7. Subscribe to this local .ics calendar
8. Start Venkman
9. Enable Profiling in Venkman
10. Go back to Sunbird and reload the calendar
11. Switch back to Venkman and export the profiling data
Here are the full results:
http://www.babylonsounds.com/calendar/venkman_profile_sunbird_0.8pre_reload.txt
http://www.babylonsounds.com/calendar/venkman_profile_sunbird_0.5_reload.txt
Here the worst contenders from the 0.8pre build for closer inspection:
calICSCalendar.js: 5000 - 1000000 milliseconds
Function Name: anonymous (Lines 187 - 253)
Total Calls: 1 (max recurse 0)
Total Time: 7093.75 (min/max/avg 7093.75/7093.75/7093.75)
Time (ex. calls): 312.5 (min/max/avg 312.5/312.5/312.5)
calICSCalendar.js: 2500 - 5000 milliseconds
Function Name: anonymous (Lines 482 - 485)
Total Calls: 1 (max recurse 0)
Total Time: 4578.13 (min/max/avg 4578.13/4578.13/4578.13)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 425 - 475)
Total Calls: 9 (max recurse 1)
Total Time: 4578.13 (min/max/avg 0/4578.13/508.68)
Time (ex. calls): 0 (min/max/avg 0/0/0)
Function Name: anonymous (Lines 416 - 422)
Total Calls: 7 (max recurse 0)
Total Time: 4296.88 (min/max/avg 0/4296.88/613.84)
Time (ex. calls): 2953.13 (min/max/avg 0/2953.13/421.88)
calMemoryCalendar.js: 2500 - 5000 milliseconds
Function Name: anonymous (Lines 339 - 431)
Total Calls: 7 (max recurse 1)
Total Time: 4578.13 (min/max/avg 125/4312.5/654.02)
Time (ex. calls): 125 (min/max/avg 15.63/62.5/17.86)
calIcsParser.js: 1000 - 2500 milliseconds
Function Name: ip_parseString (Lines 56 - 152)
Total Calls: 1 (max recurse 0)
Total Time: 1203.13 (min/max/avg 1203.13/1203.13/1203.13)
Time (ex. calls): 343.75 (min/max/avg 343.75/343.75/343.75)
calMemoryCalendar.js: 750 - 1000 milliseconds
Function Name: anonymous (Lines 125 - 181)
Total Calls: 612 (max recurse 0)
Total Time: 937.5 (min/max/avg 0/15.63/1.53)
Time (ex. calls): 46.88 (min/max/avg 0/15.63/0.08)
calEvent.js: 750 - 1000 milliseconds
Function Name: anonymous (Lines 89 - 98)
Total Calls: 20668 (max recurse 0)
Total Time: 859.38 (min/max/avg 0/15.63/0.04)
Time (ex. calls): 687.5 (min/max/avg 0/15.63/0.03)
Simon
Michiel van Leeuwen
> 1. We lose a lot of time in the GetRange function in
> calMemoryCalendar.ics and calICSCalendar.js
> (7370.53 milliseconds respectively in both files)
The problem with venkman (imo) is that it only measures the time total
spend in the function, and not the time spend in the function itself. so
if function A calls function B, and B takes a lot of time, A will also
show up as taking a lot of time. And because there are no call-stacks,
it's hard to judge where the real time killer is.
In your example, you can't tell if the provider really is the problem,
or the provider calling the callbacks which are in the views and to all
the redrawing. Or maybe it's some other callback. You just don't know.
So it's hard for me to conclude anything from the profiles.
But let me comment on one things I see:
> 16 <file:/D:/Documents%20and%20Settings/spaquet/My%20Documents/sunbird/js/calItemBase.js>
> Function Name: anonymous (Lines 60 - 68)
> Total Calls: 22104 (max recurse 0)
> Total Time: 500.71 (min/max/avg 0/20.03/0.02)
> Time (ex. calls): 500.71 (min/max/avg 0/20.03/0.02)
That's properties being slow, bug 382121 and 362762
Michiel
Michiel van Leeuwen
> Total Calls: 2 (max recurse 0)
> Total Time: 7370.53 (min/max/avg 430.62/6939.91/3685.26)
> Time (ex. calls): 0 (min/max/avg 0/0/0)
That's the actual call to getItems. Why is it called twice? Might the
unifinder. What did you have it displaying?
And which one of the two calls is the view? the slow one or the fast one?
Michiel
Andy Burns
> There have been repeated reports, that our performance for .ics
> calendars has declined since 0.5.
I hadn't noticed any performance decrease from 0.5 up to 0.7, but with
0.8pre I notice a big slowdown, my main calendar has about 3 years worth
of entries with approximately one entry per working day.
Patrick Strasser
> The problem with venkman (imo) is that it only measures the time total
> spend in the function, and not the time spend in the function itself. so
> if function A calls function B, and B takes a lot of time, A will also
> show up as taking a lot of time.
>> Function Name: anonymous (Lines 60 - 68)
>> Total Calls: 22104 (max recurse 0)
>> Total Time: 500.71 (min/max/avg 0/20.03/0.02)
This would be the time including calls for me, that is "gross time".
500.71/22104=0.023
>> Time (ex. calls): 500.71 (min/max/avg 0/20.03/0.02)
This would be the time without "child" calls, that is "net time".
This functions seems to be a callgraph leave and time consumer.
Seems quite useful to me.
Patrick
--
Engineers motto: cheap, good, fast: choose any two
Patrick Strasser <patrick dot strasser at tugraz dot at>
Student of Telematik, Techn. University Graz, Austria
Michiel van Leeuwen
> Michiel van Leeuwen schrieb am 2007-12-07 23:36:
>
> >> Function Name: anonymous (Lines 60 - 68)
> >> Total Calls: 22104 (max recurse 0)
> >> Total Time: 500.71 (min/max/avg 0/20.03/0.02)
>
> This would be the time including calls for me, that is "gross time".
> 500.71/22104=0.023
>
> >> Time (ex. calls): 500.71 (min/max/avg 0/20.03/0.02)
>
> This would be the time without "child" calls, that is "net time".
> This functions seems to be a callgraph leave and time consumer.
Yes, I saw the 'Total Time' after I posted. I posted mostly from memory,
and not by really looking at the log.
But even after i saw that line, I was still confused. For example, this one:
calEvent.js: 500 - 750 milliseconds
Function Name: anonymous (Lines 252 - 254)
Total Calls: 49642 (max recurse 0)
Total Time: 550.78 (min/max/avg 0/20.03/0.01)
Time (ex. calls): 130.18 (min/max/avg 0/10.02/0)
That function looks like this:
252 get startDate() {
253 return this.getProperty("DTSTART");
254 },
That should be 100% spend in child functions, because the function
itself does nothing. But still, it consumes time. How is that possible?
Hmm, coming to think of it, maybe it xpconnect stuff? This function can
be called from C++ components, so maybe crossing that border shows as
taking time.
Michiel
Michiel van Leeuwen
> Hi!
>
> There have been repeated reports, that our performance for .ics
> calendars has declined since 0.5. I've tried to come up and with an
> explanation for this, so I tried to profile a simple app operation.
>
saw only one new bug so far...
Michiel
Simon Paquet
Well, I wanted to get a discussion going. That was the main intent. We'll
see how it goes from there. I need to followup on Joey's post.
Simon
Simon Paquet
>> calICSCalendar.js: 5000 - 1000000 milliseconds
No idea, how can I test this?
Simon
Michiel van Leeuwen
> And on the seventh day Michiel van Leeuwen spoke:
>
>>> calICSCalendar.js: 5000 - 1000000 milliseconds
>>> Function Name: anonymous (Lines 416 - 422)
>>> Total Calls: 2 (max recurse 0)
>>> Total Time: 7370.53 (min/max/avg 430.62/6939.91/3685.26)
>>> Time (ex. calls): 0 (min/max/avg 0/0/0)
>> That's the actual call to getItems. Why is it called twice? Might the
>> unifinder. What did you have it displaying?
>> And which one of the two calls is the view? the slow one or the fast one?
>
> No idea, how can I test this?
Was the unifinder showing all events, events for just this day,
something else?
You can test is by removing the unifinder. The best way would be to hack
the code :) (remove the call to GetItems)
Michiel
Simon Paquet
>>>> calICSCalendar.js: 5000 - 1000000 milliseconds
>>>> Function Name: anonymous (Lines 416 - 422)
>>>> Total Calls: 2 (max recurse 0)
>>>> Total Time: 7370.53 (min/max/avg 430.62/6939.91/3685.26)
>>>> Time (ex. calls): 0 (min/max/avg 0/0/0)
>>>
>>> That's the actual call to getItems. Why is it called twice? Might the
>>> unifinder. What did you have it displaying?
>>> And which one of the two calls is the view? the slow one or the fast one?
>>
>> No idea, how can I test this?
>
>Was the unifinder showing all events, events for just this day,
>something else?
All events.
>You can test is by removing the unifinder. The best way would be to hack
>the code :) (remove the call to GetItems)
I commented out the following line:
http://lxr.mozilla.org/mozilla1.8/source/calendar/base/content/calendar-unifinder.js#717
This causes the unifinder to no longer show any events. However, I still
see two calls in the following functions with a current nightly:
|calCompositeCalendar.js: 5000 - 1000000 milliseconds
| Function Name: anonymous (Lines 408 - 430)
| Total Calls: 2 (max recurse 0)
| Total Time: 6531.25 (min/max/avg 437.5/6093.75/3265.63)
| Time (ex. calls): 0 (min/max/avg 0/0/0)
|
| Function Name: anonymous (Lines 519 - 545)
| Total Calls: 2 (max recurse 0)
| Total Time: 6109.38 (min/max/avg 250/5859.38/3054.69)
| Time (ex. calls): 3937.5 (min/max/avg 203.13/3734.38/1968.75)
|
|
|calICSCalendar.js: 5000 - 1000000 milliseconds
| Function Name: anonymous (Lines 425 - 475)
| Total Calls: 2 (max recurse 0)
| Total Time: 6531.25 (min/max/avg 437.5/6093.75/3265.63)
| Time (ex. calls): 0 (min/max/avg 0/0/0)
|
| Function Name: anonymous (Lines 416 - 422)
| Total Calls: 2 (max recurse 0)
| Total Time: 6531.25 (min/max/avg 437.5/6093.75/3265.63)
| Time (ex. calls): 0 (min/max/avg 0/0/0)
|
|
|calMemoryCalendar.js: 5000 - 1000000 milliseconds
| Function Name: anonymous (Lines 339 - 431)
| Total Calls: 2 (max recurse 0)
| Total Time: 6531.25 (min/max/avg 437.5/6093.75/3265.63)
| Time (ex. calls): 78.13 (min/max/avg 15.63/62.5/39.06)
Looking at the "Time (ex. calls)" lines, with one exception
(calCompositeCalendar.js - Lines 519 - 545) most of the time seems to be
spent elsewhere with those functions waiting on other functions.
Any idea what's happening there?
Michiel van Leeuwen
> All events.
That could be a bit slow.
> I commented out the following line:
>
> http://lxr.mozilla.org/mozilla1.8/source/calendar/base/content/calendar-unifinder.js#717
>
> This causes the unifinder to no longer show any events. However, I still
> see two calls in the following functions with a current nightly:
That's a bit weird. I can imagine some startup code drawing the views
twice. I saw a few other cases of that. But removing the call from the
unifinder, and still having two calls is something I don't understand.
> |calCompositeCalendar.js: 5000 - 1000000 milliseconds
> | Function Name: anonymous (Lines 519 - 545)
> | Total Calls: 2 (max recurse 0)
> | Total Time: 6109.38 (min/max/avg 250/5859.38/3054.69)
> | Time (ex. calls): 3937.5 (min/max/avg 203.13/3734.38/1968.75)
I don't understand how that functions (which does basically nothing) has
quite a bit of time in ex. calls. That makes me think that something is
wrong with the benchmark. Or with my reading of it, ofcourse.
> Looking at the "Time (ex. calls)" lines, with one exception
> (calCompositeCalendar.js - Lines 519 - 545) most of the time seems to be
> spent elsewhere with those functions waiting on other functions.
>
> Any idea what's happening there?
>
That's likely the views getting the answer about the resulting items.
Remember, this is async code. GetItems() calls back to the caller with
results. So the time the caller needs to process the calls is also
counted to the time spend in GetItems.
Michiel
Simon Paquet
>> All events.
>
>That could be a bit slow.
Yep.
>> I commented out the following line:
>>
>> http://lxr.mozilla.org/mozilla1.8/source/calendar/base/content/calendar-unifinder.js#717
>>
>> This causes the unifinder to no longer show any events. However, I still
>> see two calls in the following functions with a current nightly:
>
>That's a bit weird. I can imagine some startup code drawing the views
>twice. I saw a few other cases of that. But removing the call from the
>unifinder, and still having two calls is something I don't understand.
Any idea how I could narrow this down some more?
>> |calCompositeCalendar.js: 5000 - 1000000 milliseconds
>> | Function Name: anonymous (Lines 519 - 545)
>> | Total Calls: 2 (max recurse 0)
>> | Total Time: 6109.38 (min/max/avg 250/5859.38/3054.69)
>> | Time (ex. calls): 3937.5 (min/max/avg 203.13/3734.38/1968.75)
>
>I don't understand how that functions (which does basically nothing) has
>quite a bit of time in ex. calls. That makes me think that something is
>wrong with the benchmark. Or with my reading of it, ofcourse.
Perhaps Daniel has an idea, since he has spent some time in that file
lately. Daniel?
>> Looking at the "Time (ex. calls)" lines, with one exception
>> (calCompositeCalendar.js - Lines 519 - 545) most of the time seems to be
>> spent elsewhere with those functions waiting on other functions.
>>
>> Any idea what's happening there?
>>
>That's likely the views getting the answer about the resulting items.
Yeah, I guessed the same. It's just weird that this takes so long. I
suspect that something terribly wrong goes on here and that we have some
really low-hanging fruit to grab if we could find the cause of this.
Michiel van Leeuwen
>> That's likely the views getting the answer about the resulting items.
>
> Yeah, I guessed the same. It's just weird that this takes so long. I
> suspect that something terribly wrong goes on here and that we have some
> really low-hanging fruit to grab if we could find the cause of this.
Why is something terribly wrong? I can imagine that drawing the boxes,
figuring out the sizes, etc. takes some time. I don't see anything
terribly wrong. Sure, there might be possibilities for optimization, but
it's not really bad imo.
One would expect that the call-site would show up to, but they don't. It
should be somewhere in the xbl files. But I can't find it. Maybe venkman
ignores those files? For the views to show anything, at least some
functions from calendar-month-view.xml should be in the profile, but
there is nothing. Is it something with your setup or something with
venkman itself?
Michiel
Simon Paquet
>One would expect that the call-site would show up to, but they don't. It
>should be somewhere in the xbl files. But I can't find it. Maybe venkman
>ignores those files? For the views to show anything, at least some
>functions from calendar-month-view.xml should be in the profile, but
>there is nothing. Is it something with your setup or something with
>venkman itself?
No idea. One would have to ask the venkman devs. I'll try to find one of
them this week on IRC if I find the time.
However, just reducing a current profile from all entries with
"Time (ex. calls): 0" should show at least some culprits for our bad
performance. The TOP-3 entries alone take up nearly five seconds.
|calMemoryCalendar.js: Function Name: anonymous (Lines 339 - 431)
| Total Calls: 2 (max recurse 0)
| Time (ex. calls): 3187.5 (min/max/avg 218.75/2968.75/1593.75)
getItems: function
|calEvent.js: Function Name: anonymous (Lines 89 - 98)
| Total Calls: 22521 (max recurse 0)
| Time (ex. calls): 953.13 (min/max/avg 0/15.63/0.04)
QueryInterface: function
|calItemBase.js: Function Name: anonymous (Lines 391 - 403)
| Total Calls: 53157 (max recurse 0)
| Time (ex. calls): 812.5 (min/max/avg 0/15.63/0.02)
getProperty: function
|calItemBase.js: Function Name: anonymous (Lines 60 - 68)
| Total Calls: 21938 (max recurse 0)
| Time (ex. calls): 515.63 (min/max/avg 0/15.63/0.02)
QueryInterface: function
|calendar-view-core.xml: Function Name: __toplevel__ (Lines 101 - 118)
| Total Calls: 305 (max recurse 0)
| Time (ex. calls): 187.5 (min/max/avg 0/15.63/0.61)
|
|calEvent.js: Function Name: anonymous (Lines 252 - 254)
| Total Calls: 49534 (max recurse 0)
| Time (ex. calls): 62.5 (min/max/avg 0/15.63/0)
get startDate()
|calUtils.js: Function Name: ensureDateTime (Lines 676 - 683)
| Total Calls: 4900 (max recurse 0)
| Time (ex. calls): 31.25 (min/max/avg 0/15.63/0.01)
|
|calItemBase.js: Function Name: anonymous (Lines 786 - 791)
| Total Calls: 3909 (max recurse 0)
| Time (ex. calls): 15.63 (min/max/avg 0/15.63/0)
var getter = function
|calProviderBase.js: Function Name: cPB_QueryInterface (Lines 42 - 46)
| Total Calls: 9 (max recurse 0)
| Time (ex. calls): 15.63 (min/max/avg 0/15.63/1.74)
|
|calUtils.js: Function Name: checkIfInRange (Lines 946 - 996)
| Total Calls: 1224 (max recurse 0)
| Time (ex. calls): 93.75 (min/max/avg 0/15.63/0.08)
|
|calUtils.js: Function Name: isEvent (Lines 408 - 410)
| Total Calls: 2448 (max recurse 0)
| Time (ex. calls): 15.63 (min/max/avg 0/15.63/0.01)
Perhaps this helps someone in determining the root cause or some of the
root causes.
Simon Paquet
>>> That's likely the views getting the answer about the resulting items.
>>
>> Yeah, I guessed the same. It's just weird that this takes so long. I
>> suspect that something terribly wrong goes on here and that we have some
>> really low-hanging fruit to grab if we could find the cause of this.
>
>Why is something terribly wrong?
It takes somewhere between 5 to 6 seconds (by wall clock count) to switch
from one month to another. Thats at least one order of magnitude too
much.
>I can imagine that drawing the boxes, figuring out the sizes, etc. takes
>some time.
Sure, but not that long.
>Sure, there might be possibilities for optimization, but it's not really
>bad imo.
From a user perspective that's really bad, because the app is basically
unusable with .ics files that are larger than 100K (Such files are not
unusual). Remember this is a local file that I'm testing with. It gets
even worse with a file on a remote server, because then you can add the
network latency and download time to the numbers above.
Joey Minta
> >I can imagine that drawing the boxes, figuring out the sizes, etc. takes
> >some time.
>
> Sure, but not that long.
>
I make it a point not to disagree with developers about which areas of code
are slow, especially when they are right. mvl has a proven track record of
being knowledgable about perf hits, and his intuitions are correct here.
In an effort to save my inbox, I went ahead and collected my own data. I
did this by hand, because I shared mvl's incredulity concerning venkman's
calculation of the ex-call numbers. I used the same ics file Simon pointed
to for his original tests. The full patch I made to calendar files is
available here: http://pastebin.mozilla.org/268938 The first run confirmed
Simon's observation that there were in fact 2 calls to getItems, which led
me to insert the stack() call as well.
I'll summarize my results first. The actual output from the test is below
(1) The minimonth listener to track changes in the views actually calls
getItems as well, leading to the second call. Note however that I was
showing the calendar list tab, not the minimonth, so in this case, the call
was wasted.
(2) The sum total of the memory calendar calls is exactly equal to the
totals of the outer calls, confirming mvl's claim that the "ex-call" data
was faulty.
(3) Only 5% of the total time was spent in the provider identifying items to
be displayed. Fully 95% of the time was spent in the month-view's
onGetResult listener. In other words, all of the slowness is in the views.
(4) Profiling the view-slowness is left as an exercise to the reader. I
tried to map out a call-graph but the code has become incredibly convoluted
and I didn't want to bother trying to learn all the weird new, undocumented
queues.
(5) There is an odd disparity between the getItems times for the two calls,
which presumably should be much closer. One may wish to look into those
differences as well, but they are small compared to view-layout times.
-Joey
Output is as follows:
1:
2: getItems
3: popRefreshQueue
4: refresh
5: setDateRange
6: showDate
7: goToDay
8: moveView
9: onxblmove
10: dispatchEvent
Start (memory): 0
(done computing filters): 0
(done computing items): 48
(onGetResult done): 983
(onOpComplete done): 1
Start (ics): 0
(ics getitems finished): 1032
Start (composite): 0
(composite getitems done): 1032
1:
2: getItems
3: monthChangeListener
4: dispatchEvent
5: fireEvent
6: showMonth
7: selectDate
8: observeViewDaySelect
9: dispatchEvent
10: fireEvent
Start (memory): 0
(done computing filters): 0
(done computing items): 139
(onGetResult done): 74
(onOpComplete done): 1
Start (ics): 0
(ics getitems finished): 214
Start (composite): 0
(composite getitems done): 214
Simon Paquet
Hi Joey,
>>> I can imagine that drawing the boxes, figuring out the sizes, etc.
>>> takes some time.
>>
>> Sure, but not that long.
>>
> I make it a point not to disagree with developers about which areas
> of code are slow, especially when they are right. mvl has a proven
> track record of being knowledgable about perf hits, and his
> intuitions are correct here.
Don't get me wrong here. My point was *not* that mvl is wrong with his
statements that the code is all right in terms of performance.
My point is that waiting for more than 5 seconds to switch from one
month to another in the month view is terribly wrong from a user
perspective and may lose us more users than X great new features
like device sync, offline support, etc. may gain us.
> In an effort to save my inbox, I went ahead and collected my own
> data. I did this by hand, because I shared mvl's incredulity
> concerning venkman's calculation of the ex-call numbers. I used
> the same ics file Simon pointed to for his original tests. The full
> patch I made to calendar files is available here:
> http://pastebin.mozilla.org/268938
> The first run confirmed Simon's observation that there were in fact
> 2 calls to getItems, which led me to insert the stack() call as well.
>
> I'll summarize my results first.
Thanks for that.
> The actual output from the test is below
> (1) The minimonth listener to track changes in the views actually
> calls getItems as well, leading to the second call. Note however
> that I was showing the calendar list tab, not the minimonth, so in
> this case, the call was wasted.
> (2) The sum total of the memory calendar calls is exactly equal to
> the totals of the outer calls, confirming mvl's claim that the
> "ex-call" data was faulty.
> (3) Only 5% of the total time was spent in the provider identifying
> items to be displayed. Fully 95% of the time was spent in the
> month-view's onGetResult listener. In other words, all of the slowness
> is in the views.
This should be raised on our 0.8 agenda. I would even say that it is
worth to delay the release by a month or two to fix this.
Daniel Boelzle
...
> This should be raised on our 0.8 agenda. I would even say that it is
> worth to delay the release by a month or two to fix this.
If it turns out that the views are actually the hot area (thanks to Joey
and all involved figuring this out!), then we should definitely spend
time on optimizing them, even for 0.8.
But IMHO we should first have to dig deeper what can be done in the
views and estimate how much work it would take *before* delaying the
next release for some x months.
Daniel
Patrick Strasser
>>> I commented out the following line:
>>>
>>> http://lxr.mozilla.org/mozilla1.8/source/calendar/base/content/calendar-unifinder.js#717
>>>
>> unifinder, and still having two calls is something I don't understand.
>
> Any idea how I could narrow this down some more?
You can define a breakpoint that does not stop, but execute something
(or only stop on certain conditions), like
dump(STACK(10));
See http://www.svendtofte.com/code/learning_venkman/breakpoints.php
This lets you easily find the culprits.
Michiel van Leeuwen
> And on the seventh day Michiel van Leeuwen spoke:
>
> It takes somewhere between 5 to 6 seconds (by wall clock count) to switch
> from one month to another. Thats at least one order of magnitude too
> much.
What I wanted to say: Why should there one thing be terribly wrong? My
guess for now is that there are multiple things a little bit wrong, and
those things add up.
Michiel
Simon Paquet
That could of course also be true.
Michiel van Leeuwen
> The full patch I made to calendar files is
> available here: http://pastebin.mozilla.org/268938
Thanks for the script. I already used it, and it works nicely.
> I'll summarize my results first. The actual output from the test is below
> (1) The minimonth listener to track changes in the views actually calls
> getItems as well, leading to the second call. Note however that I was
> showing the calendar list tab, not the minimonth, so in this case, the call
> was wasted.
Ah, yes, I totally forgot about the minimonth. But that makes me wonder:
why is there no call from the unifinder?
> (4) Profiling the view-slowness is left as an exercise to the reader. I
> tried to map out a call-graph but the code has become incredibly convoluted
> and I didn't want to bother trying to learn all the weird new, undocumented
> queues.
I did that exercise, and found bug 408727. There might be more, but this
one jumped out on me.
Michiel
Joey Minta
> Ah, yes, I totally forgot about the minimonth. But that makes me wonder:
> why is there no call from the unifinder?
Because this was a profile of view-change. Navigating through a month
normally doesn't trigger any change in the unifinder. Or at least it didn't
in 0.5...
-Joey
Michiel van Leeuwen
Oh, yes. You are totally right... I feel a bit stupid now...
Michiel
Simon Paquet
>> (4) Profiling the view-slowness is left as an exercise to the reader. I
>> tried to map out a call-graph but the code has become incredibly convoluted
>> and I didn't want to bother trying to learn all the weird new, undocumented
>> queues.
>
>I did that exercise, and found bug 408727. There might be more, but this
>one jumped out on me.
Cool. A 20% - 40% performance increase for switching is great news.
Venkman shows a significant decrease of time spent in some functions.
Simon Paquet
>> This should be raised on our 0.8 agenda. I would even say that it is
>> worth to delay the release by a month or two to fix this.
>
> If it turns out that the views are actually the hot area (thanks to
> Joey and all involved figuring this out!), then we should definitely
> spend time on optimizing them, even for 0.8.
I just tried a test build with the patch for bug 382121 and the patch
for bug 408727 and it is definitely an improvement.
I would not go so far as to say that it is fast now, only that we went
from "abysmally slow" to "really slow" :-)
> But IMHO we should first have to dig deeper what can be done in the
> views and estimate how much work it would take *before* delaying the
> next release for some x months.
Well, those patches (the one for bug 382121 has already gone in) are
at least a start. Let's hope that we find more hot spots, where we
can optimize things.
Cya