[Zodb-checkins] CVS: ZODB3/ZEO - ClientCache.py:1.30.2.1

Guido van Rossum guido@python.org
Wed, 28 Aug 2002 16:27:29 -0400


Update of /cvs-repository/ZODB3/ZEO
In directory cvs.zope.org:/tmp/cvs-serv6497

Modified Files:
      Tag: zeo_trace_branch
	ClientCache.py 
Log Message:
Add tracing of cache behavior, enabled by setting $ZEO_CACHE_TRACE.


=== ZODB3/ZEO/ClientCache.py 1.30 => 1.30.2.1 ===
--- ZODB3/ZEO/ClientCache.py:1.30	Wed Aug 28 14:58:35 2002
+++ ZODB3/ZEO/ClientCache.py	Wed Aug 28 16:27:28 2002
@@ -101,6 +101,7 @@
 """
 
 import os
+import time
 import tempfile
 from struct import pack, unpack
 from thread import allocate_lock
@@ -185,6 +186,7 @@
 
         self._limit = size / 2
         self._current = current
+        self.setup_trace()
 
     def open(self):
         # Two tasks:
@@ -217,6 +219,37 @@
                 except OSError:
                     pass
 
+    def setup_trace(self):
+        # See if cache tracing is requested through $ZEO_CACHE_TRACE.
+        # If not, or if we can't write to the trace file,
+        # disable tracing by setting self.trace to a dummy function.
+        self._tracefile = None
+        tfn = os.environ.get("ZEO_CACHE_TRACE")
+        if tfn:
+            try:
+                self._tracefile = open(tfn, "a")
+                self.trace("Tracefile opened at %s" % time.ctime(time.time()),
+                           None)
+            except IOError:
+                self._tracefile = None
+        if self._tracefile is None:
+            def notrace(msg, oid, version=None, data=None, serial=None):
+                pass
+            self.trace = notrace
+
+    def trace(self, msg, oid, version=None, data=None, serial=None):
+        # When tracing is disabled, this method is hidden by a dummy.
+        parts = ["%14.3f" % time.time(), msg]
+        if oid is not None:
+            parts.append("%016x" % U64(oid))
+            if version is not None:
+                parts.append("v=%r" % version)
+                if data is not None:
+                    parts.append("n=%d" % len(data))
+                    if serial is not None:
+                        parts.append("s=%016x" % U64(serial))
+        self._tracefile.write(" ".join(parts) + "\n")
+
     def verify(self, verifyFunc):
         """Call the verifyFunc on every object in the cache.
 
@@ -230,18 +263,31 @@
         try:
             p = self._get(oid, None)
             if p is None:
+                self.trace("inva miss", oid, version)
                 return None
             f = self._f[p < 0]
             ap = abs(p)
             f.seek(ap)
             h = f.read(27)
+            if len(h) != 27:
+                log("invalidate: short record for oid %16x "
+                    "at position %d in cache file %d"
+                    % (U64(oid), ap, p < 0))
+                del self._index[oid]
+                return None
             if h[:8] != oid:
-                return
+                log("invalidate: oid mismatch: expected %16x read %16x "
+                    "at position %d in cache file %d"
+                    % (U64(oid), U64(h[:8]), ap, p < 0))
+                del self._index[oid]
+                return None
             f.seek(p+8) # Switch from reading to writing
             if version and h[15:19] != '\0\0\0\0':
+                self.trace("inva upda", oid, version)
                 # There's still relevant non-version data in the cache record
                 f.write('n')
             else:
+                self.trace("inva dele", oid, version)
                 del self._index[oid]
                 f.write('i')
         finally:
@@ -252,6 +298,7 @@
         try:
             p = self._get(oid, None)
             if p is None:
+                self.trace("load miss", oid, version)
                 return None
             f = self._f[p < 0]
             ap = abs(p)
@@ -272,15 +319,21 @@
 
             if h[8]=='n':
                 if version:
+                    self.trace("load inva", oid, version)
                     return None
                 if not dlen:
+                    # XXX This shouldn't actually happen
+                    self.trace("load dele", oid, version)
                     del self._index[oid]
                     return None
 
             if not vlen or not version:
                 if dlen:
-                    return read(dlen), h[19:]
+                    data = read(dlen)
+                    self.trace("load hit ", oid, version, data, h[19:])
+                    return data, h[19:]
                 else:
+                    self.trace("load nove", oid, version)
                     return None
 
             if dlen:
@@ -290,13 +343,17 @@
             if version != v:
                 if dlen:
                     seek(p+27)
-                    return read(dlen), h[19:]
+                    data = read(dlen)
+                    self.trace("load nvhi", oid, version, data, h[19:])
+                    return data, h[19:]
                 else:
+                    self.trace("load vmis", oid, version)
                     return None
 
             vdlen = unpack(">i", vheader[-4:])[0]
             vdata = read(vdlen)
             vserial = read(8)
+            self.trace("load vhit", oid, version, vdata, vserial)
             return vdata, vserial
         finally:
             self._release()
@@ -306,6 +363,7 @@
         try:
             if version:
                 # We need to find and include non-version data
+                self.trace("upda vers", oid, version, data, serial)
                 p = self._get(oid, None)
                 if p is None:
                     return self._store(oid, '', '', version, data, serial)
@@ -332,6 +390,7 @@
                 self._store(oid, nvdata, nvserial, version, data, serial)
             else:
                 # Simple case, just store new data:
+                self.trace("upda nove", oid, version, data, serial)
                 self._store(oid, data, serial, '', None, None)
         finally:
             self._release()
@@ -345,6 +404,7 @@
         try:
             p = self._get(oid, None)
             if p is None:
+                self.trace("modV miss", oid)
                 return None
             f = self._f[p < 0]
             ap = abs(p)
@@ -364,12 +424,16 @@
                 return None
 
             if h[8] == 'n':
+                self.trace("modV unkn", oid)
                 return None
 
             if not vlen:
+                self.trace("modV nove", oid, '')
                 return ''
             seek(dlen, 1)
-            return read(vlen)
+            version = read(vlen)
+            self.trace("modV vers", oid, version)
+            return version
         finally:
             self._release()