[ZODB-Dev] ZODB open/close profilings
Greg Ward
gward@mems-exchange.org
Tue, 10 Dec 2002 14:50:57 -0500
--Nq2Wo0NMKNjxTN9z
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
On 10 December 2002, Jeremy Hylton said:
> One inconsistency in your report, for the "open, no index..." case
> there are 7.4 seconds spent in _restore_index() and 0.0 seconds spent
> in read_index(). But read_index() is the code the runs when there is
> no index file.
Hmmm, something must have been wrong in my initial report. The data
from my latest run looks more sensible: 26.0 sec in read_index(), 22.7
sec in 806105 calls to U64(), and nothing else of consequence.
I'll attach the latest run.
Greg
PS. hotshot seems to roughly double the runtime -- if I just use
time.time() and resource.getrusage() to "profile" an open, it's about
20-22 sec. Good thing I'm not using the old pure-Python profiler!
--Nq2Wo0NMKNjxTN9z
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename=profile-stats
open, no index...
806121 function calls in 48.696 CPU seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 26.023 26.023 48.694 48.694 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:1958(read_index)
806105 22.670 0.000 22.670 0.000 /www/python/lib/python2.2/site-packages/ZODB/utils.py:56(U64)
1 0.001 0.001 48.695 48.695 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:205(__init__)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/BaseStorage.py:33(__init__)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/DB.py:39(__init__)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:593(_load)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:401(_restore_index)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/DB.py:340(open)
1 0.000 0.000 48.696 48.696 hs.py:12(open)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/Connection.py:69(__init__)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/lock_file.py:24(lock_file)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:620(load)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/Connection.py:194(_setDB)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:297(_initIndex)
1 0.000 0.000 48.696 48.696 <string>:1(?)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:308(_newIndexes)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/BaseStorage.py:97(registerDB)
0 0.000 0.000 profile:0(profiler)
close, make index...
6 function calls in 3.125 CPU seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 3.125 3.125 3.125 3.125 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:315(_save_index)
1 0.000 0.000 3.125 3.125 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:432(close)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/DB.py:124(_closeConnection)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/Connection.py:245(close)
1 0.000 0.000 3.125 3.125 <string>:1(?)
1 0.000 0.000 3.125 3.125 /www/python/lib/python2.2/site-packages/ZODB/DB.py:248(close)
0 0.000 0.000 profile:0(profiler)
open, index exists...
537422 function calls in 46.765 CPU seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 26.721 26.721 38.204 38.204 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:347(_sane)
537404 11.484 0.000 11.484 0.000 /www/python/lib/python2.2/site-packages/ZODB/utils.py:56(U64)
1 7.492 7.492 45.696 45.696 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:401(_restore_index)
1 1.065 1.065 46.765 46.765 hs.py:12(open)
2 0.001 0.001 0.001 0.001 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:297(_initIndex)
1 0.001 0.001 45.699 45.699 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:205(__init__)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/BaseStorage.py:33(__init__)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/DB.py:340(open)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:1958(read_index)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/DB.py:39(__init__)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:593(_load)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/Connection.py:69(__init__)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/lock_file.py:24(lock_file)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/Connection.py:194(_setDB)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:620(load)
1 0.000 0.000 46.765 46.765 <string>:1(?)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:308(_newIndexes)
1 0.000 0.000 0.000 0.000 /www/python/lib/python2.2/site-packages/ZODB/BaseStorage.py:97(registerDB)
0 0.000 0.000 profile:0(profiler)
close, index ok...
4 function calls in 2.663 CPU seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 2.657 2.657 2.657 2.657 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:315(_save_index)
1 0.005 0.005 2.662 2.662 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:432(close)
1 0.000 0.000 2.663 2.663 <string>:1(?)
1 0.000 0.000 2.662 2.662 /www/python/lib/python2.2/site-packages/ZODB/DB.py:248(close)
0 0.000 0.000 profile:0(profiler)
--Nq2Wo0NMKNjxTN9z--