map del efficiency python2.2 and 2.1

[John Hunter]

>>>>> "Jonathan" == Jonathan Hogg <jonathan at onegoodidea.com> writes:

    Jonathan> Ignoring the numbers, how does the program actually seem
    Jonathan> to you? With the runtime in the region of 10 to 27
    Jonathan> seconds you should be able to gauge where the time is
    Jonathan> going by just counting in your head as it runs. Does it
    Jonathan> look like it's spending many seconds finishing up?

Thanks for the detailed info on the time output.  I was referring to
the wall clock time and yes, the script does just sit there and tick
away doing nothing after the last print statement before my prompt
returns.

I cleared up one mystery.  The reason my CPU % usage was so low is
that I was running the script on an NFS client and some of the lost
time was due to the executable loading over the network.  But I still
can't explain why I am seeing the difference between 2.2 and 2.1 with
the script, which happens whether or not I run it on the NFS server or
client (and when running on the server I get near 100% CPU usage).
There is still an 8s differential that is tacked on at the end of the
2.2 run.  As I pointed out to Alex, it clearly is related to how 2.2
is deleting the map, because the 2.1-2.2 difference disappears simply
by adding 'del m' to the end of my script.

Warning!  Masochists only need continue reading.

Here are some more results from the wild and wonderful 2.1 vs 2.2.  I
have modified the script to do the deletions explicitly and report
times.  I'm also running on the NFS server.  All these numbers are
repeatable and do not reflect some oddness on an individual run since
I am getting near 100% CPU usage

# With the del m, no difference between 2.2 and 2.1

mother:~/ox2/test> time python2.1 test_allwords.py
Read len 1712676 seq: 1.820s
Loaded map with 856338 keys: 4.740s
Deleted map: 0.280s
6.680u 0.770s 0:07.45 100.0%	0+0k 0+0io 299pf+0w

mother:~/ox2/test> time python2.2 test_allwords.py
Read len 1712676 seq: 1.880s
Loaded map with 856338 keys: 4.510s
Deleted map: 0.250s
6.460u 0.780s 0:07.30 99.1%	0+0k 0+0io 350pf+0w

# Comment out the del m line, big difference between 2.2 and 2.1

mother:~/ox2/test> time python2.1 test_allwords.py
Read len 1712676 seq: 1.850s
Loaded map with 856338 keys: 4.730s
6.690u 0.770s 0:07.46 100.0%	0+0k 0+0io 299pf+0w

mother:~/ox2/test> time python2.2 test_allwords.py
Read len 1712676 seq: 1.870s
Loaded map with 856338 keys: 4.520s
14.480u 0.810s 0:15.28 100.0%	0+0k 0+0io 350pf+0w

# Now let's get really weird.  Add a 'del seq' and comment out 'del
# m'.  Python 2.1 now craps out!

mother:~/ox2/test> time python2.1 test_allwords.py
Read len 1712676 seq: 1.820s
Loaded map with 856338 keys: 4.780s
Deleted seq: 0.200s
14.610u 0.880s 0:15.57 99.4%	0+0k 0+0io 299pf+0w

mother:~/ox2/test> time python2.2 test_allwords.py
Read len 1712676 seq: 1.880s
Loaded map with 856338 keys: 4.500s
Deleted seq: 0.200s
14.550u 0.770s 0:17.73 86.4%	0+0k 0+0io 350pf+0w

What is bizarre about this is that the addition of the del seq line to
the script causes this 8s lag between the last print and the end of
the program in 2.1

Here then is the synopsis (excluded runs where %CPU < 99%)
            2.1       2.1     2.1       2.1
del m       yes       yes     no        no
del seq     yes       no      yes       no       
run time    7.9s      7.6s    15.4s     7.4s

            2.2       2.2     2.2       2.2
del m       yes       yes     no        no
del seq     yes       no      yes       no       
run time    7.6s      7.24s   15.6s     15.4s 

OK, I'll stop torturing you and me now.

John Hunter

import time

class Timer:
    """Record events and how long it takes.  The time between event is
    recorded"""

    def __init__(self):
        self.last = time.clock()
        self.events = []
    def event(self, s):
        now = time.clock()
        self.events.append( (s, now - self.last) )
        self.last = now

    def __repr__(self):
        s = ''
        for event in self.events:
            s += '%s: %1.3fs\n' % event
        return s

timer = Timer()

file = '/home/jdhunter/ox2/meta/allwords.dat'
fh = open(file, 'r')

s = fh.read()
seq = s.split()
timer.event('Read len %d seq' % len(seq))

m = {}
for i in xrange(0,len(seq),2):
    m[seq[i]] = int(seq[i+1])

timer.event('Loaded map with %d keys' % len(m.keys()))

# these are the del seq and del m lines that I commented or
#uncommented for the table above

del m
timer.event('Deleted map')

del seq
timer.event('Deleted seq')

print timer,