The performance changes I checked in last Friday, followed by a couple fixes
then and this week-end were mostly about ref collections. A bunch of code
moved to C and the remaining python code was streamlined along the way.
The guts of collection change notifications, Item._collectionChanged, was also
moved to C since it can get called a *lot*.
And finally, I fixed a low-hanging fruit in commit performance, struct
value saving and loading. The 3000 event calendar import started including
commit last week and revealed that the Date/Time/TimeDelta and DateTime types
could be vastly smarter about their performance. The same thinking has been
since then applied to the UI struct types defined in
http://svn.osafoundation.org/chandler/trunk/chandler/parcels/osaf/framework/types/DocumentTypes.py
As usual, timeit and hotshot were essential in measuring performance.
Again, all times listed below are measured on my Powerbook.
See my previous performance update for details:
http://lists.osafoundation.org/pipermail/dev/2005-September/003912.html
And, as last time, % diff = (1 - (after / before)) * 100
The timings below list timings made:
- after: r7699
- before: r7685
- then: r7538 (the 'before' of last time)
Comparisons with 'then' are comparing apples and oranges because of other
changes in the app and because vobject got twice as fast thanks to Jeffrey's
improvements. Still, I included it here because it shows the ups and
downs of the overall 3000 event calendar import test case.
The hotshot details (3000 event calendar import):
| r7699 | r7685 | % diff | r7538
---------------------------------------------------------------------------
total time | 57.4 s| 68.8 s| 16.6 % | 83.2 s
commit() | 17.4 s| 24.5 s| 28.9 % | 25.9 s
total time - commit() | 40.0 s| 44.3 s| 9.7 % | 57.3 s
---------------------------------------------------------------------------
new item creation via | | | |
Kind.newItem() | 14.1 s| 16.8 s| 13.7 % | 15.7 s
The comparison with r7538 is bogus because of changes in collections
in the app have caused a *lot* more notifications to be sent out
---------------------------------------------------------------------------
Kind._collectionChanged() | 6.8 s| 8.3 s| 18.1 % | n/a
---------------------------------------------------------------------------
Item.__init__() | 13.6 s| 15.9 s| 14.5 % | 10.2 s
Again, the comparison with r7538 is bogus because of changes in the app.
4339 items are created now vs. 3004 in r7538. Also, app collection changes
have slowed down creation of items since more notifications are sent out.
---------------------------------------------------------------------------
Item.setAttributeValue | 5.1 s| 6.0 s| 15.0 % | 14.4 s
Yet again, the comparison with r7538 is bogus because of changes in the app.
Item.setAttributeValue() now is called 37372 times vs. 35991 in r7538
---------------------------------------------------------------------------
establishing bi-refs in | | | |
Values._setValue | 4.9 s| 8.1 s| 39.5 % | 13.1 s
Yet again, the comparison with r7538 is bogus because of changes in the app.
Values._setValue now is called 17648 times vs. 15234 in r7538.
---------------------------------------------------------------------------
establishing one side of | | | |
bi-refs in a ref coll | 1.6 s| 3.4 s| 52.9 % | 6.8 s
Yet again, the comparison with r7538 is bogus because of changes in the app.
RefCollections._setRef() now is called 23771 times vs. 19461 in r7538
---------------------------------------------------------------------------
Establishing one side of a bi-ref in a ref collection now is 5.2 times faster
than in r7538. I think that - for now - this fixes bug 4132.
(6.8 / 19461) / (1.6 / 23771) ~= 5.2
Andi..
4742102 function calls (4608749 primitive calls) in 57.376 CPU seconds
Ordered by: cumulative time
List reduced from 1062 to 75 due to restriction <75>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 57.376 57.376 Sharing.py:195(get)
1 0.000 0.000 57.376 57.376 Sharing.py:625(get)
1 0.000 0.000 39.938 39.938 Sharing.py:640(_get)
1 0.001 0.001 39.937 39.937
Sharing.py:592(_conditionalGetItem)
1 0.000 0.000 39.935 39.935 Sharing.py:1067(_getItem)
1 1.166 1.166 39.935 39.935 ICalendar.py:306(importProcess)
2 0.149 0.075 17.438 8.719 DBRepositoryView.py:242(commit)
5434 0.093 0.000 16.482 0.003 DBRepositoryView.py:348(_saveItem)
5434 0.490 0.000 16.350 0.003 DBItemIO.py:34(writeItem)
3004 0.063 0.000 14.066 0.005 Kind.py:155(newItem)
3001 0.057 0.000 14.040 0.005 Calendar.py:1143(__init__)
3001 0.194 0.000 13.983 0.005 Calendar.py:226(__init__)
4207/4162 0.106 0.000 13.762 0.003 schema.py:584(__init__)
4339/4335 0.518 0.000 13.593 0.003 Item.py:27(__init__)
5434 0.353 0.000 13.592 0.003 ItemIO.py:14(writeItem)
3055 0.124 0.000 12.247 0.004 items.py:164(__init__)
1 0.503 0.503 9.278 9.278 vobject.py:670(readComponents)
5434 0.052 0.000 7.213 0.001 DBItemIO.py:224(_values)
5434 1.008 0.000 7.160 0.001 Values.py:110(_writeValues)
4283 0.437 0.000 6.799 0.002 Kind.py:923(_collectionChanged)
48935 2.169 0.000 6.103 0.000 DBItemIO.py:232(_value)
22008/9983 0.461 0.000 5.501 0.001 Sets.py:172(_collectionChanged)
5434 0.071 0.000 5.406 0.001 DBItemIO.py:228(_references)
6983 0.091 0.000 5.370 0.001 Sets.py:633(sourceChanged)
2002 0.770 0.000 5.370 0.003 Calendar.py:1171(getLocation)
5434 0.787 0.000 5.335 0.001 Values.py:653(_writeValues)
37372/37294 0.575 0.000 5.108 0.000 Item.py:148(setAttributeValue)
17648 0.687 0.000 4.907 0.000 Values.py:351(_setValue)
5174 0.073 0.000 4.536 0.001 Kind.py:905(iterItems)
36784 1.525 0.000 4.510 0.000 DBItemIO.py:342(_ref)
5174 0.080 0.000 4.403 0.001 Query.py:45(run)
12380 0.200 0.000 4.374 0.000 RefCollections.py:198(append)
5181/5174 4.318 0.001 4.322 0.001 Query.py:60(_run)
22008 1.278 0.000 4.285 0.000
collections.py:149(collectionChanged)
23697 0.168 0.000 3.834 0.000 Item.py:2063(_refList)
23697 0.348 0.000 3.663 0.000
DBRepositoryView.py:108(_createRefList)
23450 0.691 0.000 3.303 0.000 DBRefs.py:196(__init__)
3001 0.051 0.000 3.272 0.001 Sets.py:699(sourceChanged)
35175 0.220 0.000 3.202 0.000 Values.py:398(_setRef)
4331 0.281 0.000 3.031 0.001 Kind.py:604(getInitialValues)
50006/48871 0.564 0.000 3.012 0.000 DBItemIO.py:116(writeValue)
24669 0.697 0.000 2.589 0.000 DBRefs.py:234(_saveValues)
9024/3008 0.176 0.000 2.559 0.001 Sets.py:340(sourceChanged)
3979 0.025 0.000 2.319 0.001 RefCollections.py:189(add)
26902 0.694 0.000 2.307 0.000 vobject.py:412(getLogicalLines)
26902 0.453 0.000 2.213 0.000
vobject.py:592(textLineToContentLine)
5434 0.375 0.000 2.104 0.000 DBContainer.py:779(saveItem)
3000 0.036 0.000 2.092 0.001 collections.py:316(add)
6168/3001 0.121 0.000 2.074 0.001 schema.py:995(__getattr__)
23697 0.604 0.000 2.049 0.000 RefCollections.py:25(__init__)
974 0.036 0.000 2.031 0.002 Reminders.py:151(makeReminder)
51720 1.606 0.000 1.905 0.000 DBRefs.py:96(_writeRef)
3129/3001 0.047 0.000 1.897 0.001 schema.py:1195(parcel_for_module)
4611/3959 0.050 0.000 1.883 0.000 schema.py:1239(itemFor)
5/1 0.000 0.000 1.853 1.853 collections.py:141(setup)
8/1 0.001 0.000 1.842 1.842 schema.py:1166(_init_schema_item)
1 0.004 0.004 1.834 1.834 __init__.py:14(installParcel)
15225 1.705 0.000 1.785 0.000 DBContainer.py:101(put)
6001 0.066 0.000 1.685 0.000 __init__.py:44(icaluid_changed)
26902 0.421 0.000 1.637 0.000 vobject.py:185(__init__)
23771 0.970 0.000 1.601 0.000 RefCollections.py:242(_setRef)
3975/1 0.276 0.000 1.546 1.546
vobject.py:346(transformChildrenToNative)
306/266 0.011 0.000 1.493 0.006 schema.py:520(update)
30877 1.310 0.000 1.404 0.000 vobject.py:50(__init__)
4413 0.039 0.000 1.337 0.000 Item.py:1712(_setParent)
1 0.001 0.001 1.326 1.326 __init__.py:219(MakeCollections)
26900/6976 0.523 0.000 1.309 0.000 vobject.py:71(autoBehavior)
1 0.000 0.000 1.265 1.265
vobject.py:341(setBehaviorFromVersionLine)
22926/1 0.301 0.000 1.265 1.265 vobject.py:88(setBehavior)
5037/2946 0.136 0.000 1.216 0.000 Kind.py:435(iterAttributes)
42068 0.137 0.000 1.199 0.000 items.py:176(__str__)
4331 0.021 0.000 1.177 0.000 Kind.py:87(_setupClass)
51165 0.441 0.000 1.159 0.000 DBItemIO.py:305(_type)
47 0.003 0.000 1.156 0.025 Kind.py:117(_setupDescriptors)
1316/1045 0.005 0.000 1.134 0.001 schema.py:617(getKind)
6894416 function calls (6664336 primitive calls) in 68.768 CPU seconds
Ordered by: cumulative time
List reduced from 1088 to 75 due to restriction <75>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 68.768 68.768 Sharing.py:195(get)
1 0.000 0.000 68.768 68.768 Sharing.py:625(get)
1 0.000 0.000 44.375 44.375 Sharing.py:640(_get)
1 0.001 0.001 44.374 44.374
Sharing.py:592(_conditionalGetItem)
1 0.000 0.000 44.372 44.372 Sharing.py:1067(_getItem)
1 1.158 1.158 44.371 44.371 ICalendar.py:306(importProcess)
2 0.150 0.075 24.393 12.197 DBRepositoryView.py:242(commit)
5434 0.094 0.000 23.459 0.004 DBRepositoryView.py:348(_saveItem)
5434 0.489 0.000 23.324 0.004 DBItemIO.py:34(writeItem)
5434 0.358 0.000 20.881 0.004 ItemIO.py:14(writeItem)
3001 0.055 0.000 16.798 0.006 Calendar.py:1143(__init__)
3004 0.064 0.000 16.798 0.006 Kind.py:156(newItem)
3001 0.200 0.000 16.743 0.006 Calendar.py:226(__init__)
4207/4162 0.103 0.000 16.046 0.004 schema.py:584(__init__)
4339/4335 0.490 0.000 15.872 0.004 Item.py:28(__init__)
3055 0.125 0.000 14.543 0.005 items.py:164(__init__)
5434 0.052 0.000 13.627 0.003 DBItemIO.py:224(_values)
5434 1.020 0.000 13.575 0.002 Values.py:111(_writeValues)
48935 2.291 0.000 12.505 0.000 DBItemIO.py:232(_value)
1 0.518 0.518 9.627 9.627 vobject.py:670(readComponents)
124725/48871 1.317 0.000 9.276 0.000 DBItemIO.py:116(writeValue)
66784/44776 0.743 0.000 8.341 0.000 Item.py:316(_collectionChanged)
4283 0.304 0.000 8.077 0.002 Kind.py:924(_collectionChanged)
17648 0.712 0.000 8.064 0.000 Values.py:352(_setValue)
13366 1.676 0.000 7.096 0.001 Types.py:1003(writeValue)
12380 0.201 0.000 7.008 0.001 RefCollections.py:199(append)
22008/9983 0.355 0.000 6.696 0.001 Sets.py:172(_collectionChanged)
6983 0.087 0.000 6.481 0.001 Sets.py:633(sourceChanged)
5434 0.069 0.000 6.193 0.001 DBItemIO.py:228(_references)
5434 0.786 0.000 6.124 0.001 Values.py:654(_writeValues)
37372/37294 0.578 0.000 6.039 0.000 Item.py:149(setAttributeValue)
35175 0.224 0.000 5.931 0.000 Values.py:399(_setRef)
23697 0.176 0.000 5.720 0.000 Item.py:2085(_refList)
23697 0.254 0.000 5.540 0.000
DBRepositoryView.py:108(_createRefList)
36784 1.626 0.000 5.299 0.000 DBItemIO.py:342(_ref)
23450 0.531 0.000 5.269 0.000 DBRefs.py:214(__init__)
22008 1.307 0.000 4.384 0.000
collections.py:149(collectionChanged)
3979 0.025 0.000 4.343 0.001 RefCollections.py:190(add)
2002 0.799 0.000 4.263 0.002 Calendar.py:1171(getLocation)
3001 0.050 0.000 4.119 0.001 Sets.py:699(sourceChanged)
4331 0.278 0.000 3.955 0.001 Kind.py:605(getInitialValues)
3000 0.036 0.000 3.941 0.001 collections.py:316(add)
28184 0.848 0.000 3.627 0.000 LinkedMap.py:152(__setitem__)
23771 0.364 0.000 3.404 0.000 RefCollections.py:247(_setRef)
5246 0.072 0.000 3.400 0.001 Kind.py:906(iterItems)
19331 0.294 0.000 3.290 0.000 DBRefs.py:256(_setRef)
5246 0.080 0.000 3.267 0.001 Query.py:45(run)
24669 1.186 0.000 3.226 0.000 DBRefs.py:266(_saveValues)
5253/5246 3.181 0.001 3.185 0.001 Query.py:60(_run)
9024/3008 0.178 0.000 3.125 0.001 Sets.py:340(sourceChanged)
125884 0.993 0.000 2.964 0.000 DBItemIO.py:305(_type)
26902 0.710 0.000 2.571 0.000 vobject.py:412(getLogicalLines)
6168/3001 0.122 0.000 2.569 0.001 schema.py:995(__getattr__)
23474 2.427 0.000 2.427 0.000 DBRefs.py:30(__init__)
3129/3001 0.059 0.000 2.387 0.001 schema.py:1195(parcel_for_module)
4611/3959 0.052 0.000 2.373 0.001 schema.py:1239(itemFor)
5/1 0.000 0.000 2.342 2.342 collections.py:141(setup)
8/1 0.001 0.000 2.331 2.331 schema.py:1166(_init_schema_item)
23697 0.454 0.000 2.328 0.000 RefCollections.py:25(__init__)
1 0.004 0.004 2.323 2.323 __init__.py:14(installParcel)
26902 0.449 0.000 2.163 0.000
vobject.py:592(textLineToContentLine)
6001 0.050 0.000 2.017 0.000 __init__.py:44(icaluid_changed)
306/266 0.011 0.000 1.953 0.007 schema.py:520(update)
51720 1.571 0.000 1.854 0.000 DBRefs.py:114(_writeRef)
974 0.036 0.000 1.854 0.002 Reminders.py:151(makeReminder)
5434 0.378 0.000 1.793 0.000 DBContainer.py:779(saveItem)
1 0.001 0.001 1.697 1.697 __init__.py:219(MakeCollections)
5037/2946 0.145 0.000 1.646 0.001 Kind.py:436(iterAttributes)
3975/1 0.285 0.000 1.599 1.599
vobject.py:346(transformChildrenToNative)
4331 0.021 0.000 1.594 0.000 Kind.py:88(_setupClass)
26902 0.449 0.000 1.589 0.000 vobject.py:185(__init__)
47 0.003 0.000 1.573 0.033 Kind.py:118(_setupDescriptors)
1316/1045 0.006 0.000 1.476 0.001 schema.py:617(getKind)
48013 0.479 0.000 1.460 0.000 LinkedMap.py:32(_setNext)
44/6 0.005 0.000 1.459 0.243 schema.py:499(_init_schema_item)
7983271 function calls (7782644 primitive calls) in 83.202 CPU seconds
Ordered by: cumulative time
List reduced from 533 to 50 due to restriction <50>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 83.202 83.202 Sharing.py:191(get)
1 0.000 0.000 83.202 83.202 Sharing.py:615(get)
1 0.000 0.000 57.290 57.290 Sharing.py:630(_get)
1 0.001 0.001 57.289 57.289
Sharing.py:582(_conditionalGetItem)
1 0.000 0.000 57.286 57.286 Sharing.py:1059(_getItem)
1 1.689 1.689 57.286 57.286 ICalendar.py:294(importProcess)
2 0.166 0.083 25.912 12.956 DBRepositoryView.py:242(commit)
5046 0.090 0.000 24.913 0.005 DBRepositoryView.py:348(_saveItem)
5046 0.463 0.000 24.786 0.005 DBItemIO.py:35(writeItem)
5046 0.323 0.000 21.930 0.004 ItemIO.py:14(writeItem)
1 0.531 0.531 17.632 17.632 vobject.py:710(readComponents)
3000 0.061 0.000 15.653 0.005 Kind.py:156(newItem)
3000 0.049 0.000 15.524 0.005 Calendar.py:1086(__init__)
3000 0.142 0.000 15.475 0.005 Calendar.py:227(__init__)
35991/35990 0.537 0.000 14.384 0.000 Item.py:188(setAttributeValue)
5046 0.048 0.000 13.702 0.003 DBItemIO.py:225(_values)
5046 1.295 0.000 13.654 0.003 Values.py:209(_writeValues)
15234 0.632 0.000 13.076 0.001 Values.py:475(_setValue)
45900 2.029 0.000 11.427 0.000 DBItemIO.py:233(_value)
3004 0.105 0.000 10.208 0.003 items.py:167(__init__)
30468 0.477 0.000 9.347 0.000 Values.py:532(_setRef)
10229 0.187 0.000 8.928 0.001 RefCollections.py:204(append)
135586/117587 1.054 0.000 8.889 0.000 Item.py:1154(setDirty)
120130/45763 1.222 0.000 8.573 0.000 DBItemIO.py:117(writeValue)
3978 0.087 0.000 8.522 0.002 schema.py:584(__init__)
3978 0.387 0.000 8.402 0.002 Item.py:28(__init__)
58746/52746 0.798 0.000 7.933 0.000 Item.py:1224(_fireChanges)
26902 1.077 0.000 7.402 0.000
vobject.py:623(textLineToContentLine)
7227 0.111 0.000 7.383 0.001 Values.py:527(_addValue)
5046 0.068 0.000 7.229 0.001 DBItemIO.py:229(_references)
5046 1.033 0.000 7.161 0.001 Values.py:784(_writeValues)
18957 0.411 0.000 7.116 0.000 DBRefs.py:264(_setRef)
19461 0.196 0.000 6.767 0.000 RefCollections.py:256(_setRef)
13015 1.642 0.000 6.756 0.001 Types.py:1002(writeValue)
58746/52746 2.410 0.000 6.035 0.000 Monitors.py:84(invoke)
26902 3.407 0.000 5.713 0.000 vobject.py:475(parseLine)
23439 0.669 0.000 5.634 0.000 LinkedMap.py:156(__setitem__)
35987 1.559 0.000 5.376 0.000 DBItemIO.py:344(_ref)
3974 0.026 0.000 5.337 0.001 RefCollections.py:195(add)
2002 0.645 0.000 5.118 0.003 Calendar.py:1114(getLocation)
3975/1 0.280 0.000 4.871 4.871
vobject.py:345(transformChildrenToNative)
3000 0.037 0.000 4.552 0.002 collections.py:313(add)
3973 0.079 0.000 4.370 0.001 Kind.py:900(iterItems)
25925/22925 0.189 0.000 4.341 0.000 vobject.py:95(transformToNative)
23001 0.166 0.000 4.229 0.000 Item.py:2203(_refList)
3973 0.073 0.000 4.116 0.001 Query.py:45(run)
23001 0.257 0.000 4.059 0.000
DBRepositoryView.py:108(_createRefList)
3973 4.041 0.001 4.042 0.001 Query.py:60(_run)
22962 0.510 0.000 3.799 0.000 DBRefs.py:222(__init__)
3978 0.435 0.000 3.657 0.001 Kind.py:605(getInitialValues)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
Open Source Applications Foundation "Dev" mailing list
http://lists.osafoundation.org/mailman/listinfo/dev
