[ZODB-Dev] More timing data

[Greg Ward]

On 11 December 2002, Christian Reis said:
> Can we get some profiling data <wink> to see where the increase in time
> is actually happening? If you have the time it would be great!

If I (wink wink) "have the time" eh? -- yuk yuk, very funny.
(Hmmm, lame puns don't really work by email.  Oh well.)

OK, here are some numbers.  This sure is easier than looking at the code
and trying to figure out what's taking so long.

open-noindex, ZODB 3.1:

   ncalls  tottime  percall  cumtime  percall function
        1   29.859   29.859   48.353   48.353 FileStorage.read_index()
   806105   18.494    0.000   18.494    0.000 utils.U64()

(No other function took a measurable amount of time.)

open-noindex, ZODB trunk:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   35.815   35.815   78.419   78.419 FileStorage.read_index()
   806105   14.794    0.000   14.794    0.000 utils.u64()
   268701   11.900    0.000   17.245    0.000 fsIndex.__setitem__()
        1    6.882    6.882   24.127   24.127 fsIndex.update()
   268701    5.346    0.000    5.346    0.000 fsIndex.num2str()
   268701    3.683    0.000    3.683    0.000 fsIndex.get()

(A few other functions took measurable time, but all were << 1 sec
total.)

open, ZODB 3.1 (index exists):

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   27.359   27.359   37.792   37.792 FileStorage._sane()
   537404   10.432    0.000   10.432    0.000 utils.U64()
        1    7.298    7.298   45.089   45.089 FileStorage._restore_index()

open, ZODB trunk:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   33.000   33.000   57.301   57.301 FileStorage._sane()
   537404   10.030    0.000   10.030    0.000 utils.py.u64()
   268701    7.825    0.000   14.272    0.000 fsIndex.get()
   268702    6.447    0.000    6.447    0.000 fsIndex.str2num()
        1    2.895    2.895   60.196   60.196 FileStorage._restore_index()

Conclusion: the fsIndex patch seems to slow things down compared to the
old, simple way of loading the entire, enormous index pickles.  That's
not a big surprise; reducing memory use typically leads to increased
runtime.  What I'd like to know is why the trunk code also takes more
memory!  But the real culprit in the "index exists" case is still
_sane().  I think it would be just peachy if that method disappeared in
ZODB 3.2.  Wonder if we can improve things any for 3.1.1 though...

        Greg
-- 
Greg Ward - software developer                gward@mems-exchange.org
MEMS Exchange                            http://www.mems-exchange.org