[ZODB-Dev] ZODB open/close profilings
Greg Ward
gward@mems-exchange.org
Tue, 10 Dec 2002 14:05:51 -0500
--UlVJffcvxoiEqYs2
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In private email last week, I whined to Jeremy about how long it takes
to open a FileStorage ZODB. He was a bit surprised at the times I
quoted for my box (800 MHz Athlon, 256 MB RAM, fast SCSI disk [well, the
fact that the cable costs almost as much as some hard drives means it
*must* be fast, right?], Linux 2.4), and asked me to do some profiling.
So I did. I wrote a little script that:
* deletes the index file and profiles an open, ie.:
storage = FileStorage(...)
db = DB(storage)
conn = db.open()
* profiles db.close() (should generate the index file, right?)
* profile a second open (index file exists and is up-to-date)
* profile a second db.close() (no need to regenerate index file)
Oh, the database in question is just under 80 MB freshly packed, and has
somewhere in the neighbourhood of 250,000 objects in it. I'm using
hotshot for the profiling. Using ZODB 3.1 and ZEO 2.0.
Executive summary:
* the presence or absence of an index file makes very little
difference: 49 sec to open without index, 48 sec to open with
* it might be worth rewriting the OID packing/unpacking functions
in C; opening the database calls U64() 537,404 times, accounting
for ~12 sec of the ~48 sec total open time
* but the real culprit is FileStorage._sane(), which takes 28 sec
of the ~48 sec total opening time
I'll attach the per-function results. I'm going to see if I can't get
hotshot to give me per-line results next.
Greg
--
Greg Ward - software developer gward@mems-exchange.org
MEMS Exchange http://www.mems-exchange.org
--UlVJffcvxoiEqYs2
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename=profile-stats
open, no index...
537422 function calls in 49.266 CPU seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 28.621 28.621 41.913 41.913 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:347(_sane)
537404 13.291 0.000 13.291 0.000 /www/python/lib/python2.2/site-packages/ZODB/utils.py:56(U64)
1 7.351 7.351 49.264 49.264 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:401(_restore_index)
1 0.001 0.001 49.265 49.265 /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:1958(read_index)
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/DB.py:340(open)
1 0.000 0.000 49.266 49.266 hs.py:12(open)
2 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 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 49.266 49.266 <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...
4 function calls in 3.661 CPU seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 3.661 3.661 3.661 3.661 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:315(_save_index)
1 0.000 0.000 3.661 3.661 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:432(close)
1 0.000 0.000 3.661 3.661 <string>:1(?)
1 0.000 0.000 3.661 3.661 /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 47.934 CPU seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 28.137 28.137 39.985 39.985 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:347(_sane)
537404 11.847 0.000 11.847 0.000 /www/python/lib/python2.2/site-packages/ZODB/utils.py:56(U64)
1 7.948 7.948 47.932 47.932 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:401(_restore_index)
1 0.001 0.001 47.934 47.934 /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:1958(read_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 47.934 47.934 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__)
2 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 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 47.934 47.934 <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.815 CPU seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 2.815 2.815 2.815 2.815 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:315(_save_index)
1 0.000 0.000 2.815 2.815 /www/python/lib/python2.2/site-packages/ZODB/FileStorage.py:432(close)
1 0.000 0.000 2.815 2.815 <string>:1(?)
1 0.000 0.000 2.815 2.815 /www/python/lib/python2.2/site-packages/ZODB/DB.py:248(close)
0 0.000 0.000 profile:0(profiler)
--UlVJffcvxoiEqYs2--