Fixed numerous bugs in the ZEO cache tracing and analysys code.

Cache simulation, while not perfect, seems to be much more accurate
now than it was before.

The ZEO cache trace statistics and simulation scripts have been
given more descriptive names and moved to the ZEO scripts package.

src/CHANGES.txt

@@ -26,6 +26,13 @@ Bugs fixed
 
   https://bugs.launchpad.net/zodb/+bug/143237
 
+- There were numerous bugs in the ZEO cache tracing and analysys code.
+  Cache simulation, while not perfect, seems to be much more accurate
+  now than it was before.
+
+  The ZEO cache trace statistics and simulation scripts have been
+  given more descriptive names and moved to the ZEO scripts package.
+
 3.10.0b1 (2010-05-18)
 =====================
 

src/ZEO/cache.py

@@ -379,6 +379,7 @@ class ClientCache(object):
     # Close the underlying file.  No methods accessing the cache should be
     # used after this.
     def close(self):
+        self._unsetup_trace()
         f = self.f
         self.f = None
         if f is not None:
@@ -726,6 +727,10 @@ class ClientCache(object):
     # self._tracefile.  If not, or we can't write to the trace file, disable
     # tracing by setting self._trace to a dummy function, and set
     # self._tracefile to None.
+    _tracefile = None
+    def _trace(self, *a, **kw):
+        pass
+
     def _setup_trace(self, path):
         _tracefile = None
         if path and os.environ.get("ZEO_CACHE_TRACE"):
@@ -738,7 +743,6 @@ class ClientCache(object):
                 logger.info("opened tracefile %r", tfn)
 
         if _tracefile is None:
-            self._trace = lambda *a, **k: None
             return
 
         now = time.time
@@ -747,7 +751,7 @@ class ClientCache(object):
             # The first hex digit shows the operation, the second the outcome.
             # This method has been carefully tuned to be as fast as possible.
             # Note: when tracing is disabled, this method is hidden by a dummy.
-            encoded = (dlen + 255) & 0x7fffff00 | code
+            encoded = (dlen << 8) + code
             if tid is None:
                 tid = z64
             if end_tid is None:
@@ -762,8 +766,15 @@ class ClientCache(object):
                 raise
 
         self._trace = _trace
+        self._tracefile = _tracefile
         _trace(0x00)
 
+    def _unsetup_trace(self):
+        if self._tracefile is not None:
+            del self._trace
+            self._tracefile.close()
+            del self._tracefile
+
 def sync(f):
     f.flush()
 

src/ZODB/scripts/stats.py → src/ZEO/scripts/cache_stats.py

@@ -66,7 +66,9 @@ def usage(msg):
     print >> sys.stderr, msg
     print >> sys.stderr, __doc__
 
-def main():
+def main(args=None):
+    if args is None:
+        args = sys.argv[1:]
     # Parse options
     verbose = False
     quiet = False
@@ -76,7 +78,7 @@ def main():
     interval = 15*60 # Every 15 minutes
     heuristic = False
     try:
-        opts, args = getopt.getopt(sys.argv[1:], "hi:qsSvX")
+        opts, args = getopt.getopt(args, "hi:qsSvX")
     except getopt.error, msg:
         usage(msg)
         return 2
@@ -154,6 +156,8 @@ def main():
     FMT_SIZE = struct.calcsize(FMT)
     assert FMT_SIZE == 26
     # Read file, gathering statistics, and printing each record if verbose.
+    print ' '*16, "%7s %7s %7s %7s" % ('loads', 'hits', 'inv(h)', 'writes'),
+    print 'hitrate'
     try:
         while 1:
             r = f_read(FMT_SIZE)
@@ -182,7 +186,7 @@ def main():
                 thisinterval = ts // interval
                 h0 = ts
             he = ts
-            dlen, code = code & 0x7fffff00, code & 0xff
+            dlen, code = (code & 0x7fffff00) >> 8, code & 0xff
             if dlen:
                 datarecords += 1
                 datasize += dlen
@@ -245,10 +249,10 @@ def main():
         print "First time: %s" % time.ctime(t0)
         print "Last time:  %s" % time.ctime(te)
         print "Duration:   %s seconds" % addcommas(te-t0)
-        print "Data recs:  %s (%.1f%%), average size %.1f KB" % (
+        print "Data recs:  %s (%.1f%%), average size %d bytes" % (
             addcommas(datarecords),
             100.0 * datarecords / records,
-            datasize / 1024.0 / datarecords)
+            datasize / datarecords)
         print "Hit rate:   %.1f%% (load hits / loads)" % hitrate(bycode)
         print
         codes = bycode.keys()
@@ -303,22 +307,27 @@ def dumpbysize(bysize, how, how2):
                                 loads)
 
 def dumpbyinterval(byinterval, h0, he):
-    loads = hits = 0
+    loads = hits = invals = writes = 0
     for code in byinterval:
-        if code & 0x70 == 0x20:
+        if code & 0x20:
             n = byinterval[code]
             loads += n
             if code in (0x22, 0x26):
                 hits += n
-    if not loads:
-        return
+        elif code & 0x40:
+            writes +=  byinterval[code]
+        elif code & 0x10:
+            if code != 0x10:
+                invals += byinterval[code]
+
     if loads:
-        hr = 100.0 * hits / loads
+        hr = "%5.1f%%" % (100.0 * hits / loads)
     else:
-        hr = 0.0
-    print "%s-%s %10s loads, %10s hits,%5.1f%% hit rate" % (
+        hr = 'n/a'
+
+    print "%s-%s %7s %7s %7s %7s %7s" % (
         time.ctime(h0)[4:-8], time.ctime(he)[14:-8],
-        addcommas(loads), addcommas(hits), hr)
+        loads, hits, invals, writes, hr)
 
 def hitrate(bycode):
     loads = hits = 0

src/ZODB/tests/util.py

@@ -138,3 +138,20 @@ def store(storage, oid, value='x', serial=ZODB.utils.z64):
     storage.store(oid, serial, value, '', t)
     storage.tpc_vote(t)
     storage.tpc_finish(t)
+
+def mess_with_time(test=None, globs=None, now=1278864701.5):
+    now = [now]
+    def faux_time():
+        now[0] += 1
+        return now[0]
+
+    if test is None and globs is not None:
+        # sigh
+        faux_time.globs = globs
+        test = faux_time
+
+    import time
+    zope.testing.setupstack.register(test, setattr, time, 'time', time.time)
+
+    time.time = faux_time
+