On Dec 23, 2006, at 11:23 AM, Ed Leafe wrote:
> I always like to make sure that I know just what the problem is
> before determining what the best solution is. Profiling has usually
> verified my hunches, but has also revealed that the main bottleneck
> was not exactly what I had assumed.
OK, I downloaded the latest OneToManyApp, and added the @profile
decorator to dBizobj.requery(). I then requeried with no filters, and
then skipped through the Customer data so that the child data was
requeried. Here's the output:
*** PROFILER RESULTS ***
requery (/Library/Frameworks/Python.framework/Versions/2.4/lib/
python2.4/site-packages/dabo/biz/dBizobj.py:614)
function called 34 times
39339 function calls (38896 primitive calls) in 0.650 CPU
seconds
Ordered by: cumulative time, internal time, call count
List reduced from 208 to 40 due to restriction <40>
ncalls tottime percall cumtime percall filename:lineno(function)
34/33 0.010 0.000 0.650 0.020 dBizobj.py:614(requery)
33 0.000 0.000 0.650 0.020 profile:0(<function
requery at 0x789eb0>)
34 0.000 0.000 0.550 0.016 dCursorMixin.py:306
(requery)
35 0.020 0.001 0.490 0.014 dCursorMixin.py:203
(execute)
35 0.010 0.000 0.290 0.008 cursors.py:308(_query)
35 0.000 0.000 0.290 0.008 cursors.py:127(execute)
35 0.010 0.000 0.270 0.008 :0(fetch_row)
35 0.000 0.000 0.270 0.008 cursors.py:279
(_fetch_row)
35 0.000 0.000 0.270 0.008 cursors.py:313
(_post_get_result)
441 0.020 0.000 0.200 0.000 decimal.py:473(__new__)
2436 0.070 0.000 0.170 0.000 dCursorMixin.py:145
(correctFieldType)
441 0.040 0.000 0.110 0.000 decimal.py:3034
(_string2exact)
357 0.060 0.000 0.060 0.000 times.py:73(Date_or_None)
2436 0.040 0.000 0.060 0.000 __init__.py:61
(getDaboType)
7707 0.050 0.000 0.050 0.000 :0(isinstance)
507/66 0.020 0.000 0.050 0.001 dCursorMixin.py:1210
(addMemento)
69 0.010 0.000 0.040 0.001 dBizobj.py:1061(getPK)
34 0.000 0.000 0.040 0.001 dBizobj.py:800(_moveToPK)
34 0.020 0.001 0.030 0.001 dCursorMixin.py:1268
(moveToPK)
19 0.010 0.001 0.030 0.002 dLocalize.py:30
(__add_apptrans)
69 0.000 0.000 0.030 0.000 dCursorMixin.py:690
(getFieldVal)
19 0.000 0.000 0.030 0.002 dLocalize.py:46(_)
441 0.020 0.000 0.020 0.000 decimal.py:2925
(_isinfinity)
1764 0.020 0.000 0.020 0.000 :0(group)
34 0.010 0.000 0.020 0.001 dBizobj.py:671
(setChildLinkFilter)
1233 0.010 0.000 0.020 0.000 dCursorMixin.py:1870
(_getEncoding)
3049 0.020 0.000 0.020 0.000 :0(get)
884 0.020 0.000 0.020 0.000 :0(len)
441 0.020 0.000 0.020 0.000 decimal.py:2933(_isnan)
441 0.020 0.000 0.020 0.000 :0(map)
152 0.010 0.000 0.020 0.000 UserDict.py:52(get)
38 0.000 0.000 0.020 0.001 gettext.py:408(find)
38 0.000 0.000 0.020 0.001 gettext.py:448
(translation)
19 0.000 0.000 0.020 0.001 dLocalize.py:8
(__translation)
441 0.010 0.000 0.010 0.000 dMemento.py:6(__init__)
35 0.010 0.000 0.010 0.000 :0(query)
35 0.000 0.000 0.010 0.000 cursors.py:270(_do_query)
34 0.000 0.000 0.010 0.000 dBizobj.py:1069
(getParentPK)
1548 0.010 0.000 0.010 0.000 dCursorMixin.py:1802
(_getBackendObject)
946 0.010 0.000 0.010 0.000 :0(copy)
addMemento was called 507 times for a cumulative time of 0.05
seconds out of 0.65 seconds. I don't see anything else on this that
has to do with the memento system.
The other place where you thought the system was slowing down was
when we have to check for changes before requerying, or doing
anything that would possibly delete unsaved changes. So I profiled
the dForm.confirmChanges() method. In order to remove the time for
the 'areYouSure' dialog, I commented out that line and just set
response=True, forcing the save. Here are those results:
*** PROFILER RESULTS ***
confirmChanges (/Library/Frameworks/Python.framework/Versions/2.4/lib/
python2.4/site-packages/dabo/ui/uiwx/dForm.py:85)
function called 3 times
34257 function calls (33728 primitive calls) in 0.530 CPU
seconds
Ordered by: cumulative time, internal time, call count
List reduced from 349 to 40 due to restriction <40>
ncalls tottime percall cumtime percall filename:lineno(function)
3 0.000 0.000 0.530 0.177 dForm.py:85
(confirmChanges)
3 0.000 0.000 0.530 0.177 profile:0(<function
confirmChanges at 0x42ae8f0>)
190/4 0.010 0.000 0.520 0.130 dBizobj.py:503(scan)
272 0.010 0.000 0.460 0.002 dBizobj.py:785
(_moveToRowNum)
193 0.020 0.000 0.430 0.002 dBizobj.py:1326
(_setCurrentCursor)
193 0.000 0.000 0.430 0.002 dBizobj.py:936
(setCurrentParent)
73 0.010 0.000 0.410 0.006 dBizobj.py:121
(createCursor)
1 0.000 0.000 0.370 0.370 Form.py:95(save)
2/1 0.000 0.000 0.360 0.360 dBizobj.py:255(saveAll)
1 0.000 0.000 0.360 0.360 dForm.py:257(save)
292 0.000 0.000 0.310 0.001 :0(apply)
146 0.000 0.000 0.310 0.002 dCursorMixin.py:28
(__init__)
146 0.000 0.000 0.310 0.002 dBizobj.py:171(__init__)
146 0.000 0.000 0.310 0.002 dBackend.py:50(getCursor)
146 0.000 0.000 0.310 0.002 dConnection.py:37
(getCursor)
146 0.160 0.001 0.300 0.002 propertyHelperMixin.py:
226(getPropertyList)
146 0.000 0.000 0.300 0.002 dObject.py:35(__init__)
146 0.000 0.000 0.300 0.002 propertyHelperMixin.py:
49(_extractKeywordProperties)
188/86 0.000 0.000 0.160 0.002 dBizobj.py:835
(isAnyChanged)
7974 0.070 0.000 0.070 0.000 :0(has_key)
264/202 0.000 0.000 0.050 0.000 dBizobj.py:854(isChanged)
73 0.010 0.000 0.040 0.001 dCursorMixin.py:1773
(_setAutoCommit)
1934 0.030 0.000 0.030 0.000 :0(append)
73 0.030 0.000 0.030 0.000 :0(autocommit)
73 0.020 0.000 0.030 0.000 dBizobj.py:167
(_getCursorClass)
73 0.000 0.000 0.030 0.000 dBackend.py:189
(setAutoCommitStatus)
949 0.030 0.000 0.030 0.000 :0(dir)
264 0.010 0.000 0.030 0.000 dCursorMixin.py:608
(isChanged)
165/125 0.000 0.000 0.030 0.000 dBizobj.py:844
(_checkForChanges)
95/84 0.000 0.000 0.020 0.000 dBizobj.py:284
(_saveRowIfChanged)
15/12 0.000 0.000 0.020 0.002 dBizobj.py:1034
(requeryAllChildren)
12 0.000 0.000 0.020 0.002 dBizobj.py:1543
(_setRowNumber)
3 0.000 0.000 0.020 0.007 dBizobj.py:613(requery)
1898 0.010 0.000 0.010 0.000 :0(count)
358 0.010 0.000 0.010 0.000 dBizobj.py:1400
(_getKeyField)
281 0.000 0.000 0.010 0.000 dBizobj.py:1059(getPK)
590 0.010 0.000 0.010 0.000 dCursorMixin.py:1938
(_getRowNumber)
306 0.010 0.000 0.010 0.000 :0(register_converter)
284 0.010 0.000 0.010 0.000 dCursorMixin.py:1944
(_setRowNumber)
264 0.010 0.000 0.010 0.000 dCursorMixin.py:627
(isRowChanged)
Here we see that dBizobj.isAnyChanged() took 0.16 out of the total
time of 0.53 seconds; however, all this method does is call scan() on
the _checkForChanges() method. _checkForChanges() only took 0.03
seconds, meaning that the bulk of the time used by isAnyChanged was
for the implementation of the scan loop, not for the actual checking
of changes!
A little profiling gives a lot of useful information.
-- Ed Leafe
-- http://leafe.com
-- http://dabodev.com
_______________________________________________
Post Messages to: [email protected]
Subscription Maintenance: http://leafe.com/mailman/listinfo/dabo-dev
