profiling and performance of shelves

[Eric S. Johansson]

was profiling some of my code trying to figure out just why it was running slow and I discovered that shelves containing dictionaries were significantly slower than those containing simple tuples.  for example, on a Pentium III/600 MHz machine the code below ran in 1.12 seconds but when I substituted a simple tuple for the shelf, it ran significantly faster (0.13 seconds).  I'm confused as to why shelving dictionaries (all elements textual) should take so much longer is the pickel process that complex?.

----- test framework -----
#!/usr/bin/python

import sys

development_path = "/usr/local/camram/modules"
sys.path.insert(1,development_path)

import dbm_utils
import camram_utils
import configuration

#set the local context
config_data = configuration.configuration("esj")

def main():

    # wrapper for shelf which also includes locking, file creation etc.
    # returns object derived from type shelve.
    spamtrap_cache = camram_utils.message_cache( configuration_data = config_data)

    cnt =0
    x = 0
    
	# test code.  Don't use without adding filename to message_cache
##     while x<500:
##         spamtrap_cache[str(x)]=(x,"const string")
##         x=x+1
        
    for i in spamtrap_cache.keys():
        token = spamtrap_cache[i]
        cnt=cnt+1

    print cnt
    print token
    
import profile
profile.run('main()', '/tmp/speed')

import pstats

stats = pstats.Stats('/tmp/speed')
stats.strip_dirs().sort_stats('cumulative').print_stats()
stats.print_callees()

----  profile output

Tue Jun 22 14:25:48 2004    /tmp/speed

         12479 function calls in 1.120 CPU seconds

  Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.120    1.120 <string>:1(?)
        1    0.000    0.000    1.120    1.120 profile:0(main())
        1    0.030    0.030    1.120    1.120 speed.py:13(main)
      566    0.960    0.002    1.080    0.002 shelve.py:69(__getitem__)
    11887    0.120    0.000    0.120    0.000 <string>:0(?)
        1    0.010    0.010    0.010    0.010 shelve.py:55(keys)
        2    0.000    0.000    0.000    0.000 posixpath.py:362(normpath)
        0    0.000             0.000          profile:0(profiler)
        1    0.000    0.000    0.000    0.000 shelve.py:82(close)
        1    0.000    0.000    0.000    0.000 whichdb.py:5(whichdb)
        1    0.000    0.000    0.000    0.000 anydbm.py:69(open)
        2    0.000    0.000    0.000    0.000 configuration.py:294(__getitem__)
        2    0.000    0.000    0.000    0.000 configuration.py:355(path_process)
        1    0.000    0.000    0.000    0.000 dbm_utils.py:53(bias_anydbm)
        1    0.000    0.000    0.000    0.000 shelve.py:52(__init__)
        1    0.000    0.000    0.000    0.000 dbm_utils.py:359(__init__)
        2    0.000    0.000    0.000    0.000 configuration.py:80(base_pathname)
        2    0.000    0.000    0.000    0.000 posixpath.py:299(expanduser)
        1    0.000    0.000    0.000    0.000 portalocker.py:68(lock)
        1    0.000    0.000    0.000    0.000 shelve.py:89(__del__)
        1    0.000    0.000    0.000    0.000 camram_utils.py:329(close)
        2    0.000    0.000    0.000    0.000 posixpath.py:330(expandvars)
        1    0.000    0.000    0.000    0.000 camram_utils.py:314(__init__)



   Ordered by: cumulative time

Function                            called...
<string>:1(?)                        shelve.py:89(__del__)(1)    0.000
                                     speed.py:13(main)(1)    1.120
profile:0(main())                    <string>:1(?)(1)    1.120
speed.py:13(main)                    camram_utils.py:314(__init__)(1)    0.000
                                     shelve.py:55(keys)(1)    0.010
                                     shelve.py:69(__getitem__)(566)    1.080
shelve.py:69(__getitem__)            <string>:0(?)(11887)    0.120
<string>:0(?)                        --
shelve.py:55(keys)                   --
posixpath.py:362(normpath)           --
profile:0(profiler)                  profile:0(main())(1)    1.120
shelve.py:82(close)                  --
whichdb.py:5(whichdb)                --
anydbm.py:69(open)                   whichdb.py:5(whichdb)(1)    0.000
configuration.py:294(__getitem__)    configuration.py:355(path_process)(2)    0.000
configuration.py:355(path_process)   configuration.py:80(base_pathname)(2)    0.000
dbm_utils.py:53(bias_anydbm)         --
shelve.py:52(__init__)               --
dbm_utils.py:359(__init__)           anydbm.py:69(open)(1)    0.000
                                     dbm_utils.py:53(bias_anydbm)(1)    0.000
                                     shelve.py:52(__init__)(1)    0.000
configuration.py:80(base_pathname)   posixpath.py:299(expanduser)(2)    0.000
                                     posixpath.py:330(expandvars)(2)    0.000
                                     posixpath.py:362(normpath)(2)    0.000
posixpath.py:299(expanduser)         --
portalocker.py:68(lock)              --
shelve.py:89(__del__)                camram_utils.py:329(close)(1)    0.000
camram_utils.py:329(close)           shelve.py:82(close)(1)    0.000
posixpath.py:330(expandvars)         --
camram_utils.py:314(__init__)        configuration.py:294(__getitem__)(2)    0.000
                                     dbm_utils.py:359(__init__)(1)    0.000
                                     portalocker.py:68(lock)(1)    0.000