[Zodb-checkins] SVN: ZODB/branches/3.10/src/ZEO/ Made a small improvement to the client cache to that makes it slightly

Jim Fulton jim at zope.com
Mon Apr 11 17:24:55 EDT 2011


Log message for revision 121394:
  Made a small improvement to the client cache to that makes it slightly
  MRUish.
  
  In some experiments, this led to significant reductions in cache miss
  rates.
  

Changed:
  U   ZODB/branches/3.10/src/ZEO/cache.py
  U   ZODB/branches/3.10/src/ZEO/scripts/cache_simul.py
  U   ZODB/branches/3.10/src/ZEO/tests/test_cache.py

-=-
Modified: ZODB/branches/3.10/src/ZEO/cache.py
===================================================================
--- ZODB/branches/3.10/src/ZEO/cache.py	2011-04-11 21:24:53 UTC (rev 121393)
+++ ZODB/branches/3.10/src/ZEO/cache.py	2011-04-11 21:24:55 UTC (rev 121394)
@@ -152,7 +152,7 @@
     # default of 20MB.  The default here is misleading, though, since
     # ClientStorage is the only user of ClientCache, and it always passes an
     # explicit size of its own choosing.
-    def __init__(self, path=None, size=200*1024**2):
+    def __init__(self, path=None, size=200*1024**2, rearrange=.8):
 
         # - `path`:  filepath for the cache file, or None (in which case
         #   a temp file will be created)
@@ -163,6 +163,11 @@
         size = max(size, ZEC_HEADER_SIZE)
         self.maxsize = size
 
+        # rearrange: if we read a current record and it's more than
+        # rearrange*size from the end, then copy it forward to keep it
+        # from being evicted.
+        self.rearrange = rearrange * size
+
         # The number of records in the cache.
         self._len = 0
 
@@ -497,6 +502,7 @@
         size, saved_oid, tid, end_tid, lver, ldata = unpack(
             ">I8s8s8sHI", read(34))
         assert saved_oid == oid, (ofs, self.f.tell(), oid, saved_oid)
+        assert end_tid == z64, (ofs, self.f.tell(), oid, tid, end_tid)
         assert lver == 0, "Versions aren't supported"
 
         data = read(ldata)
@@ -508,6 +514,25 @@
 
         self._n_accesses += 1
         self._trace(0x22, oid, tid, end_tid, ldata)
+
+        ofsofs = self.currentofs - ofs
+        if ofsofs < 0:
+            ofsofs += self.maxsize
+
+        if (ofsofs > self.rearrange and
+            self.maxsize > 10*len(data) and
+            size > 4):
+            # The record is far back and might get evicted, but it's
+            # valuable, so move it forward.
+
+            # Remove fromn old loc:
+            del self.current[oid]
+            self.f.seek(ofs)
+            self.f.write('f'+pack(">I", size))
+
+            # Write to new location:
+            self._store(oid, tid, None, data, size)
+
         return data, tid
 
     ##
@@ -599,6 +624,16 @@
         self._n_added_bytes += size
         self._len += 1
 
+        self._store(oid, start_tid, end_tid, data, size)
+
+        if end_tid:
+            self._trace(0x54, oid, start_tid, end_tid, dlen=len(data))
+        else:
+            self._trace(0x52, oid, start_tid, dlen=len(data))
+
+    def _store(self, oid, start_tid, end_tid, data, size):
+        # Low-level store used by store and load
+
         # In the next line, we ask for an extra to make sure we always
         # have a free block after the new alocated block.  This free
         # block acts as a ring pointer, so that on restart, we start
@@ -618,6 +653,7 @@
             extra = 'f' + pack(">I", excess)
 
         ofs = self.currentofs
+        seek = self.f.seek
         seek(ofs)
         write = self.f.write
 
@@ -639,13 +675,12 @@
 
         if end_tid:
             self._set_noncurrent(oid, start_tid, ofs)
-            self._trace(0x54, oid, start_tid, end_tid, dlen=len(data))
         else:
             self.current[oid] = ofs
-            self._trace(0x52, oid, start_tid, dlen=len(data))
 
         self.currentofs += size
 
+
     ##
     # If `tid` is None,
     # forget all knowledge of `oid`.  (`tid` can be None only for
@@ -660,7 +695,6 @@
     # - oid object id
     # - tid the id of the transaction that wrote a new revision of oid,
     #        or None to forget all cached info about oid.
-
     @locked
     def invalidate(self, oid, tid):
         ofs = self.current.get(oid)

Modified: ZODB/branches/3.10/src/ZEO/scripts/cache_simul.py
===================================================================
--- ZODB/branches/3.10/src/ZEO/scripts/cache_simul.py	2011-04-11 21:24:53 UTC (rev 121393)
+++ ZODB/branches/3.10/src/ZEO/scripts/cache_simul.py	2011-04-11 21:24:55 UTC (rev 121394)
@@ -19,6 +19,7 @@
 Options:
 -s size: cache size in MB (default 20 MB)
 -i: summarizing interval in minutes (default 15; max 60)
+-r: rearrange factor
 
 Note:
 
@@ -52,18 +53,22 @@
     # Parse options.
     MB = 1<<20
     cachelimit = 20*MB
+    rearrange = 0.8
     simclass = CircularCacheSimulation
     interval_step = 15
     try:
-        opts, args = getopt.getopt(args, "s:i:")
+        opts, args = getopt.getopt(args, "s:i:r:")
     except getopt.error, msg:
         usage(msg)
         return 2
+
     for o, a in opts:
         if o == '-s':
             cachelimit = int(float(a)*MB)
         elif o == '-i':
             interval_step = int(a)
+        elif o == '-r':
+            rearrange = float(a)
         else:
             assert False, (o, a)
 
@@ -103,8 +108,8 @@
             return 1
 
     # Create simulation object.
-    sim = simclass(cachelimit)
-    interval_sim = simclass(cachelimit)
+    sim = simclass(cachelimit, rearrange)
+    interval_sim = simclass(cachelimit, rearrange)
 
     # Print output header.
     sim.printheader()
@@ -141,6 +146,8 @@
             if last_interval is not None:
                 interval_sim.report()
                 interval_sim.restart()
+                if not interval_sim.warm:
+                    sim.restart()
             last_interval = this_interval
         sim.event(ts, dlen, version, code, oid, start_tid, end_tid)
         interval_sim.event(ts, dlen, version, code, oid, start_tid, end_tid)
@@ -160,10 +167,12 @@
     finish() method also calls report().
     """
 
-    def __init__(self, cachelimit):
+    def __init__(self, cachelimit, rearrange):
         self.cachelimit = cachelimit
+        self.rearrange = rearrange
         # Initialize global statistics.
         self.epoch = None
+        self.warm = False
         self.total_loads = 0
         self.total_hits = 0       # subclass must increment
         self.total_invals = 0     # subclass must increment
@@ -284,20 +293,19 @@
 
 # For use in CircularCacheSimulation.
 class CircularCacheEntry(object):
-    __slots__ = (# object key:  an (oid, start_tid) pair, where
-                 # start_tid is the tid of the transaction that created
-                 # this revision of oid
-                 'key',
+    __slots__ = (
+        # object key: an (oid, start_tid) pair, where start_tid is the
+        # tid of the transaction that created this revision of oid
+        'key',
 
-                 # tid of transaction that created the next revision;
-                 # z64 iff this is the current revision
-                 'end_tid',
+        # tid of transaction that created the next revision; z64 iff
+        # this is the current revision
+        'end_tid',
 
-                 # Offset from start of file to the object's data
-                 # record; this includes all overhead bytes (status
-                 # byte, size bytes, etc).
-                 'offset',
-                )
+        # Offset from start of file to the object's data record; this
+        # includes all overhead bytes (status byte, size bytes, etc).
+        'offset',
+        )
 
     def __init__(self, key, end_tid, offset):
         self.key = key
@@ -316,10 +324,12 @@
 
     extras = "evicts", "inuse"
 
-    def __init__(self, cachelimit):
+    evicts = 0
+
+    def __init__(self, cachelimit, rearrange):
         from ZEO import cache
 
-        Simulation.__init__(self, cachelimit)
+        Simulation.__init__(self, cachelimit, rearrange)
         self.total_evicts = 0  # number of cache evictions
 
         # Current offset in file.
@@ -348,6 +358,8 @@
 
     def restart(self):
         Simulation.restart(self)
+        if self.evicts:
+            self.warm = True
         self.evicts = 0
         self.evicted_hit = self.evicted_miss = 0
 
@@ -358,6 +370,20 @@
             if oid in self.current: # else it's a cache miss
                 self.hits += 1
                 self.total_hits += 1
+
+                tid = self.current[oid]
+                entry = self.key2entry[(oid, tid)]
+                offset_offset = self.offset - entry.offset
+                if offset_offset < 0:
+                    offset_offset += self.cachelimit
+                    assert offset_offset >= 0
+
+                if offset_offset > self.rearrange * self.cachelimit:
+                    # we haven't accessed it in a while.  Move it forward
+                    size = self.filemap[entry.offset][0]
+                    self._remove(*entry.key)
+                    self.add(oid, size, tid)
+
             elif oid in self.evicted:
                 size, e = self.evicted[oid]
                 self.write(oid, size, e.key[1], z64, 1)

Modified: ZODB/branches/3.10/src/ZEO/tests/test_cache.py
===================================================================
--- ZODB/branches/3.10/src/ZEO/tests/test_cache.py	2011-04-11 21:24:53 UTC (rev 121393)
+++ ZODB/branches/3.10/src/ZEO/tests/test_cache.py	2011-04-11 21:24:55 UTC (rev 121394)
@@ -553,52 +553,52 @@
     Jul 11 12:11-14     180       1       2     197    0.6%
     Jul 11 12:15-29     818     107       9     793   13.1%
     Jul 11 12:30-44     818     213      22     687   26.0%
-    Jul 11 12:45-59     818     297      20     603   36.3%
-    Jul 11 13:00-14     818     297      35     603   36.3%
-    Jul 11 13:15-29     818     280      29     620   34.2%
-    Jul 11 13:30-44     819     275      26     625   33.6%
-    Jul 11 13:45-59     818     254      24     646   31.1%
-    Jul 11 14:00-14     818     300      32     600   36.7%
-    Jul 11 14:15-29     818     267      35     633   32.6%
-    Jul 11 14:30-44     818     309      37     591   37.8%
-    Jul 11 14:45-59     819     271      26     629   33.1%
-    Jul 11 15:00-14     818     292      30     608   35.7%
+    Jul 11 12:45-59     818     291      19     609   35.6%
+    Jul 11 13:00-14     818     295      36     605   36.1%
+    Jul 11 13:15-29     818     277      31     623   33.9%
+    Jul 11 13:30-44     819     276      29     624   33.7%
+    Jul 11 13:45-59     818     251      25     649   30.7%
+    Jul 11 14:00-14     818     295      27     605   36.1%
+    Jul 11 14:15-29     818     262      33     638   32.0%
+    Jul 11 14:30-44     818     297      32     603   36.3%
+    Jul 11 14:45-59     819     268      23     632   32.7%
+    Jul 11 15:00-14     818     291      30     609   35.6%
     Jul 11 15:15-15       2       1       0       1   50.0%
     <BLANKLINE>
-    Read 18,837 trace records (640,450 bytes) in 0.0 seconds
+    Read 18,876 trace records (641,776 bytes) in 0.0 seconds
     Versions:   0 records used a version
     First time: Sun Jul 11 12:11:41 2010
     Last time:  Sun Jul 11 15:15:01 2010
     Duration:   11,000 seconds
-    Data recs:  11,000 (58.4%), average size 1106 bytes
-    Hit rate:   31.6% (load hits / loads)
+    Data recs:  11,000 (58.3%), average size 1108 bytes
+    Hit rate:   31.2% (load hits / loads)
     <BLANKLINE>
             Count Code Function (action)
                 1  00  _setup_trace (initialization)
-              673  10  invalidate (miss)
-              327  1c  invalidate (hit, saving non-current)
-            6,836  20  load (miss)
-            3,164  22  load (hit)
-            7,836  52  store (current, non-version)
+              682  10  invalidate (miss)
+              318  1c  invalidate (hit, saving non-current)
+            6,875  20  load (miss)
+            3,125  22  load (hit)
+            7,875  52  store (current, non-version)
 
     >>> ZEO.scripts.cache_stats.main('-q cache.trace'.split())
                        loads    hits  inv(h)  writes hitrate
     <BLANKLINE>
-    Read 18,837 trace records (640,450 bytes) in 0.0 seconds
+    Read 18,876 trace records (641,776 bytes) in 0.0 seconds
     Versions:   0 records used a version
     First time: Sun Jul 11 12:11:41 2010
     Last time:  Sun Jul 11 15:15:01 2010
     Duration:   11,000 seconds
-    Data recs:  11,000 (58.4%), average size 1106 bytes
-    Hit rate:   31.6% (load hits / loads)
+    Data recs:  11,000 (58.3%), average size 1108 bytes
+    Hit rate:   31.2% (load hits / loads)
     <BLANKLINE>
             Count Code Function (action)
                 1  00  _setup_trace (initialization)
-              673  10  invalidate (miss)
-              327  1c  invalidate (hit, saving non-current)
-            6,836  20  load (miss)
-            3,164  22  load (hit)
-            7,836  52  store (current, non-version)
+              682  10  invalidate (miss)
+              318  1c  invalidate (hit, saving non-current)
+            6,875  20  load (miss)
+            3,125  22  load (hit)
+            7,875  52  store (current, non-version)
 
     >>> ZEO.scripts.cache_stats.main('-v cache.trace'.split())
     ... # doctest: +ELLIPSIS
@@ -620,27 +620,27 @@
     Jul 11 15:14:58 20              b8a 0000000000000000 0000000000000000 -
     Jul 11 15:14:58 52              b8a 00000000000003e9 0000000000000000 - 838
     Jul 11 15:14:59 22             1085 0000000000000357 0000000000000000 - 217
-    Jul 11 15:00-14     818     292      30     608   35.7%
+    Jul 11 15:00-14     818     291      30     609   35.6%
     Jul 11 15:15:00 22             1072 000000000000037e 0000000000000000 - 204
     Jul 11 15:15:01 20             16c5 0000000000000000 0000000000000000 -
     Jul 11 15:15:01 52             16c5 00000000000003e9 0000000000000000 - 1712
     Jul 11 15:15-15       2       1       0       1   50.0%
     <BLANKLINE>
-    Read 18,837 trace records (640,450 bytes) in 0.0 seconds
+    Read 18,876 trace records (641,776 bytes) in 0.0 seconds
     Versions:   0 records used a version
     First time: Sun Jul 11 12:11:41 2010
     Last time:  Sun Jul 11 15:15:01 2010
     Duration:   11,000 seconds
-    Data recs:  11,000 (58.4%), average size 1106 bytes
-    Hit rate:   31.6% (load hits / loads)
+    Data recs:  11,000 (58.3%), average size 1108 bytes
+    Hit rate:   31.2% (load hits / loads)
     <BLANKLINE>
             Count Code Function (action)
                 1  00  _setup_trace (initialization)
-              673  10  invalidate (miss)
-              327  1c  invalidate (hit, saving non-current)
-            6,836  20  load (miss)
-            3,164  22  load (hit)
-            7,836  52  store (current, non-version)
+              682  10  invalidate (miss)
+              318  1c  invalidate (hit, saving non-current)
+            6,875  20  load (miss)
+            3,125  22  load (hit)
+            7,875  52  store (current, non-version)
 
     >>> ZEO.scripts.cache_stats.main('-h cache.trace'.split())
                        loads    hits  inv(h)  writes hitrate
@@ -649,33 +649,33 @@
     Jul 11 12:11-14     180       1       2     197    0.6%
     Jul 11 12:15-29     818     107       9     793   13.1%
     Jul 11 12:30-44     818     213      22     687   26.0%
-    Jul 11 12:45-59     818     297      20     603   36.3%
-    Jul 11 13:00-14     818     297      35     603   36.3%
-    Jul 11 13:15-29     818     280      29     620   34.2%
-    Jul 11 13:30-44     819     275      26     625   33.6%
-    Jul 11 13:45-59     818     254      24     646   31.1%
-    Jul 11 14:00-14     818     300      32     600   36.7%
-    Jul 11 14:15-29     818     267      35     633   32.6%
-    Jul 11 14:30-44     818     309      37     591   37.8%
-    Jul 11 14:45-59     819     271      26     629   33.1%
-    Jul 11 15:00-14     818     292      30     608   35.7%
+    Jul 11 12:45-59     818     291      19     609   35.6%
+    Jul 11 13:00-14     818     295      36     605   36.1%
+    Jul 11 13:15-29     818     277      31     623   33.9%
+    Jul 11 13:30-44     819     276      29     624   33.7%
+    Jul 11 13:45-59     818     251      25     649   30.7%
+    Jul 11 14:00-14     818     295      27     605   36.1%
+    Jul 11 14:15-29     818     262      33     638   32.0%
+    Jul 11 14:30-44     818     297      32     603   36.3%
+    Jul 11 14:45-59     819     268      23     632   32.7%
+    Jul 11 15:00-14     818     291      30     609   35.6%
     Jul 11 15:15-15       2       1       0       1   50.0%
     <BLANKLINE>
-    Read 18,837 trace records (640,450 bytes) in 0.0 seconds
+    Read 18,876 trace records (641,776 bytes) in 0.0 seconds
     Versions:   0 records used a version
     First time: Sun Jul 11 12:11:41 2010
     Last time:  Sun Jul 11 15:15:01 2010
     Duration:   11,000 seconds
-    Data recs:  11,000 (58.4%), average size 1106 bytes
-    Hit rate:   31.6% (load hits / loads)
+    Data recs:  11,000 (58.3%), average size 1108 bytes
+    Hit rate:   31.2% (load hits / loads)
     <BLANKLINE>
             Count Code Function (action)
                 1  00  _setup_trace (initialization)
-              673  10  invalidate (miss)
-              327  1c  invalidate (hit, saving non-current)
-            6,836  20  load (miss)
-            3,164  22  load (hit)
-            7,836  52  store (current, non-version)
+              682  10  invalidate (miss)
+              318  1c  invalidate (hit, saving non-current)
+            6,875  20  load (miss)
+            3,125  22  load (hit)
+            7,875  52  store (current, non-version)
     <BLANKLINE>
     Histogram of object load frequency
     Unique oids: 4,585
@@ -699,42 +699,42 @@
     Jul 11 12:11-14     180       1       2     197    0.6%
     Jul 11 12:15-29     818     107       9     793   13.1%
     Jul 11 12:30-44     818     213      22     687   26.0%
-    Jul 11 12:45-59     818     297      20     603   36.3%
-    Jul 11 13:00-14     818     297      35     603   36.3%
-    Jul 11 13:15-29     818     280      29     620   34.2%
-    Jul 11 13:30-44     819     275      26     625   33.6%
-    Jul 11 13:45-59     818     254      24     646   31.1%
-    Jul 11 14:00-14     818     300      32     600   36.7%
-    Jul 11 14:15-29     818     267      35     633   32.6%
-    Jul 11 14:30-44     818     309      37     591   37.8%
-    Jul 11 14:45-59     819     271      26     629   33.1%
-    Jul 11 15:00-14     818     292      30     608   35.7%
+    Jul 11 12:45-59     818     291      19     609   35.6%
+    Jul 11 13:00-14     818     295      36     605   36.1%
+    Jul 11 13:15-29     818     277      31     623   33.9%
+    Jul 11 13:30-44     819     276      29     624   33.7%
+    Jul 11 13:45-59     818     251      25     649   30.7%
+    Jul 11 14:00-14     818     295      27     605   36.1%
+    Jul 11 14:15-29     818     262      33     638   32.0%
+    Jul 11 14:30-44     818     297      32     603   36.3%
+    Jul 11 14:45-59     819     268      23     632   32.7%
+    Jul 11 15:00-14     818     291      30     609   35.6%
     Jul 11 15:15-15       2       1       0       1   50.0%
     <BLANKLINE>
-    Read 18,837 trace records (640,450 bytes) in 0.0 seconds
+    Read 18,876 trace records (641,776 bytes) in 0.0 seconds
     Versions:   0 records used a version
     First time: Sun Jul 11 12:11:41 2010
     Last time:  Sun Jul 11 15:15:01 2010
     Duration:   11,000 seconds
-    Data recs:  11,000 (58.4%), average size 1106 bytes
-    Hit rate:   31.6% (load hits / loads)
+    Data recs:  11,000 (58.3%), average size 1108 bytes
+    Hit rate:   31.2% (load hits / loads)
     <BLANKLINE>
             Count Code Function (action)
                 1  00  _setup_trace (initialization)
-              673  10  invalidate (miss)
-              327  1c  invalidate (hit, saving non-current)
-            6,836  20  load (miss)
-            3,164  22  load (hit)
-            7,836  52  store (current, non-version)
+              682  10  invalidate (miss)
+              318  1c  invalidate (hit, saving non-current)
+            6,875  20  load (miss)
+            3,125  22  load (hit)
+            7,875  52  store (current, non-version)
     <BLANKLINE>
     Histograms of object sizes
     <BLANKLINE>
     <BLANKLINE>
-    Unique sizes written: 1,781
+    Unique sizes written: 1,782
           size   objs writes
-           200      6      6
+           200      5      5
            201      4      4
-           202      5      5
+           202      4      4
            203      1      1
            204      1      1
            205      6      6
@@ -742,9 +742,9 @@
     ...
          1,995      1      2
          1,996      2      2
-         1,997      2      3
+         1,997      1      1
          1,998      2      2
-         1,999      2      2
+         1,999      2      4
          2,000      1      1
 
     >>> ZEO.scripts.cache_stats.main('-S cache.trace'.split())
@@ -754,16 +754,16 @@
     Jul 11 12:11-14     180       1       2     197    0.6%
     Jul 11 12:15-29     818     107       9     793   13.1%
     Jul 11 12:30-44     818     213      22     687   26.0%
-    Jul 11 12:45-59     818     297      20     603   36.3%
-    Jul 11 13:00-14     818     297      35     603   36.3%
-    Jul 11 13:15-29     818     280      29     620   34.2%
-    Jul 11 13:30-44     819     275      26     625   33.6%
-    Jul 11 13:45-59     818     254      24     646   31.1%
-    Jul 11 14:00-14     818     300      32     600   36.7%
-    Jul 11 14:15-29     818     267      35     633   32.6%
-    Jul 11 14:30-44     818     309      37     591   37.8%
-    Jul 11 14:45-59     819     271      26     629   33.1%
-    Jul 11 15:00-14     818     292      30     608   35.7%
+    Jul 11 12:45-59     818     291      19     609   35.6%
+    Jul 11 13:00-14     818     295      36     605   36.1%
+    Jul 11 13:15-29     818     277      31     623   33.9%
+    Jul 11 13:30-44     819     276      29     624   33.7%
+    Jul 11 13:45-59     818     251      25     649   30.7%
+    Jul 11 14:00-14     818     295      27     605   36.1%
+    Jul 11 14:15-29     818     262      33     638   32.0%
+    Jul 11 14:30-44     818     297      32     603   36.3%
+    Jul 11 14:45-59     819     268      23     632   32.7%
+    Jul 11 15:00-14     818     291      30     609   35.6%
     Jul 11 15:15-15       2       1       0       1   50.0%
 
     >>> ZEO.scripts.cache_stats.main('-X cache.trace'.split())
@@ -773,33 +773,33 @@
     Jul 11 12:11-14     180       1       2     197    0.6%
     Jul 11 12:15-29     818     107       9     793   13.1%
     Jul 11 12:30-44     818     213      22     687   26.0%
-    Jul 11 12:45-59     818     297      20     603   36.3%
-    Jul 11 13:00-14     818     297      35     603   36.3%
-    Jul 11 13:15-29     818     280      29     620   34.2%
-    Jul 11 13:30-44     819     275      26     625   33.6%
-    Jul 11 13:45-59     818     254      24     646   31.1%
-    Jul 11 14:00-14     818     300      32     600   36.7%
-    Jul 11 14:15-29     818     267      35     633   32.6%
-    Jul 11 14:30-44     818     309      37     591   37.8%
-    Jul 11 14:45-59     819     271      26     629   33.1%
-    Jul 11 15:00-14     818     292      30     608   35.7%
+    Jul 11 12:45-59     818     291      19     609   35.6%
+    Jul 11 13:00-14     818     295      36     605   36.1%
+    Jul 11 13:15-29     818     277      31     623   33.9%
+    Jul 11 13:30-44     819     276      29     624   33.7%
+    Jul 11 13:45-59     818     251      25     649   30.7%
+    Jul 11 14:00-14     818     295      27     605   36.1%
+    Jul 11 14:15-29     818     262      33     638   32.0%
+    Jul 11 14:30-44     818     297      32     603   36.3%
+    Jul 11 14:45-59     819     268      23     632   32.7%
+    Jul 11 15:00-14     818     291      30     609   35.6%
     Jul 11 15:15-15       2       1       0       1   50.0%
     <BLANKLINE>
-    Read 18,837 trace records (640,450 bytes) in 0.0 seconds
+    Read 18,876 trace records (641,776 bytes) in 0.0 seconds
     Versions:   0 records used a version
     First time: Sun Jul 11 12:11:41 2010
     Last time:  Sun Jul 11 15:15:01 2010
     Duration:   11,000 seconds
-    Data recs:  11,000 (58.4%), average size 1106 bytes
-    Hit rate:   31.6% (load hits / loads)
+    Data recs:  11,000 (58.3%), average size 1108 bytes
+    Hit rate:   31.2% (load hits / loads)
     <BLANKLINE>
             Count Code Function (action)
                 1  00  _setup_trace (initialization)
-              673  10  invalidate (miss)
-              327  1c  invalidate (hit, saving non-current)
-            6,836  20  load (miss)
-            3,164  22  load (hit)
-            7,836  52  store (current, non-version)
+              682  10  invalidate (miss)
+              318  1c  invalidate (hit, saving non-current)
+            6,875  20  load (miss)
+            3,125  22  load (hit)
+            7,875  52  store (current, non-version)
 
     >>> ZEO.scripts.cache_stats.main('-i 5 cache.trace'.split())
                        loads    hits  inv(h)  writes hitrate
@@ -812,53 +812,53 @@
     Jul 11 12:30-34     272      60       8     240   22.1%
     Jul 11 12:35-39     273      68       6     232   24.9%
     Jul 11 12:40-44     273      85       8     215   31.1%
-    Jul 11 12:45-49     273      85       7     215   31.1%
-    Jul 11 12:50-54     272     105       9     195   38.6%
-    Jul 11 12:55-59     273     107       4     193   39.2%
-    Jul 11 13:00-04     273      93      12     207   34.1%
-    Jul 11 13:05-09     273     103       7     197   37.7%
-    Jul 11 13:10-14     272     101      16     199   37.1%
-    Jul 11 13:15-19     273      93       9     207   34.1%
-    Jul 11 13:20-24     273      94       9     206   34.4%
-    Jul 11 13:25-29     272      93      11     207   34.2%
-    Jul 11 13:30-34     273      84      14     216   30.8%
-    Jul 11 13:35-39     273     102       6     198   37.4%
-    Jul 11 13:40-44     273      89       6     211   32.6%
-    Jul 11 13:45-49     272      81       6     219   29.8%
-    Jul 11 13:50-54     273      87       8     213   31.9%
-    Jul 11 13:55-59     273      86      10     214   31.5%
-    Jul 11 14:00-04     273      96      12     204   35.2%
-    Jul 11 14:05-09     272      95      11     205   34.9%
-    Jul 11 14:10-14     273     109       9     191   39.9%
-    Jul 11 14:15-19     273      92       9     208   33.7%
-    Jul 11 14:20-24     272      84      17     216   30.9%
-    Jul 11 14:25-29     273      91       9     209   33.3%
-    Jul 11 14:30-34     273     106      13     194   38.8%
-    Jul 11 14:35-39     273      90      13     210   33.0%
-    Jul 11 14:40-44     272     113      11     187   41.5%
-    Jul 11 14:45-49     273      83      10     217   30.4%
-    Jul 11 14:50-54     273     101       9     199   37.0%
-    Jul 11 14:55-59     273      87       7     213   31.9%
-    Jul 11 15:00-04     272      99       6     201   36.4%
-    Jul 11 15:05-09     273      95      12     205   34.8%
-    Jul 11 15:10-14     273      98      12     202   35.9%
+    Jul 11 12:45-49     273      84       6     216   30.8%
+    Jul 11 12:50-54     272     104       9     196   38.2%
+    Jul 11 12:55-59     273     103       4     197   37.7%
+    Jul 11 13:00-04     273      92      12     208   33.7%
+    Jul 11 13:05-09     273     103       8     197   37.7%
+    Jul 11 13:10-14     272     100      16     200   36.8%
+    Jul 11 13:15-19     273      91      11     209   33.3%
+    Jul 11 13:20-24     273      96       9     204   35.2%
+    Jul 11 13:25-29     272      90      11     210   33.1%
+    Jul 11 13:30-34     273      82      14     218   30.0%
+    Jul 11 13:35-39     273     102       9     198   37.4%
+    Jul 11 13:40-44     273      92       6     208   33.7%
+    Jul 11 13:45-49     272      82       6     218   30.1%
+    Jul 11 13:50-54     273      83       8     217   30.4%
+    Jul 11 13:55-59     273      86      11     214   31.5%
+    Jul 11 14:00-04     273      95      11     205   34.8%
+    Jul 11 14:05-09     272      91      10     209   33.5%
+    Jul 11 14:10-14     273     109       6     191   39.9%
+    Jul 11 14:15-19     273      89       9     211   32.6%
+    Jul 11 14:20-24     272      84      16     216   30.9%
+    Jul 11 14:25-29     273      89       8     211   32.6%
+    Jul 11 14:30-34     273      97      12     203   35.5%
+    Jul 11 14:35-39     273      93      10     207   34.1%
+    Jul 11 14:40-44     272     107      10     193   39.3%
+    Jul 11 14:45-49     273      80       8     220   29.3%
+    Jul 11 14:50-54     273     100       8     200   36.6%
+    Jul 11 14:55-59     273      88       7     212   32.2%
+    Jul 11 15:00-04     272      99       8     201   36.4%
+    Jul 11 15:05-09     273      95      11     205   34.8%
+    Jul 11 15:10-14     273      97      11     203   35.5%
     Jul 11 15:15-15       2       1       0       1   50.0%
     <BLANKLINE>
-    Read 18,837 trace records (640,450 bytes) in 0.0 seconds
+    Read 18,876 trace records (641,776 bytes) in 0.0 seconds
     Versions:   0 records used a version
     First time: Sun Jul 11 12:11:41 2010
     Last time:  Sun Jul 11 15:15:01 2010
     Duration:   11,000 seconds
-    Data recs:  11,000 (58.4%), average size 1106 bytes
-    Hit rate:   31.6% (load hits / loads)
+    Data recs:  11,000 (58.3%), average size 1108 bytes
+    Hit rate:   31.2% (load hits / loads)
     <BLANKLINE>
             Count Code Function (action)
                 1  00  _setup_trace (initialization)
-              673  10  invalidate (miss)
-              327  1c  invalidate (hit, saving non-current)
-            6,836  20  load (miss)
-            3,164  22  load (hit)
-            7,836  52  store (current, non-version)
+              682  10  invalidate (miss)
+              318  1c  invalidate (hit, saving non-current)
+            6,875  20  load (miss)
+            3,125  22  load (hit)
+            7,875  52  store (current, non-version)
 
     >>> ZEO.scripts.cache_simul.main('-s 2 -i 5 cache.trace'.split())
     CircularCacheSimulation, cache size 2,097,152 bytes
@@ -870,39 +870,39 @@
     Jul 11 12:30   4:59     272      60      8    240   22.1%       0    67.1
     Jul 11 12:35   4:59     273      68      6    232   24.9%       0    79.8
     Jul 11 12:40   4:59     273      85      8    215   31.1%       0    91.4
-    Jul 11 12:45   4:59     273      85      7    215   31.1%      61   100.0
-    Jul 11 12:50   4:59     272     105      9    195   38.6%     193   100.0
-    Jul 11 12:55   4:59     273     107      4    193   39.2%     184   100.0
-    Jul 11 13:00   4:59     273      93     12    207   34.1%     215    99.9
-    Jul 11 13:05   4:59     273     103      7    197   37.7%     191    99.9
-    Jul 11 13:10   4:59     272     101     16    199   37.1%     191    99.9
-    Jul 11 13:15   4:59     273      93      9    207   34.1%     227    99.9
-    Jul 11 13:20   4:59     273      94      9    206   34.4%     211    99.9
-    Jul 11 13:25   4:59     272      93     11    207   34.2%     208    99.9
-    Jul 11 13:30   4:59     273      84     14    216   30.8%     221    99.9
-    Jul 11 13:35   4:59     273     102      6    198   37.4%     201    99.9
-    Jul 11 13:40   4:59     273      88      6    212   32.2%     215   100.0
-    Jul 11 13:45   4:59     272      81      5    219   29.8%     209   100.0
-    Jul 11 13:50   4:59     273      87      8    213   31.9%     223   100.0
-    Jul 11 13:55   4:59     273      86     10    214   31.5%     196    99.9
-    Jul 11 14:00   4:59     273      96     12    204   35.2%     195   100.0
-    Jul 11 14:05   4:59     272      95     11    205   34.9%     201    99.9
-    Jul 11 14:10   4:59     273     110      9    190   40.3%     189    99.9
-    Jul 11 14:15   4:59     273      94      9    206   34.4%     210    99.9
-    Jul 11 14:20   4:59     272      87     17    213   32.0%     207   100.0
-    Jul 11 14:25   4:59     273      91     10    209   33.3%     214    99.9
-    Jul 11 14:30   4:59     273     106     13    194   38.8%     210   100.0
-    Jul 11 14:35   4:59     273      90     13    210   33.0%     206   100.0
-    Jul 11 14:40   4:59     272     113     11    187   41.5%     180   100.0
-    Jul 11 14:45   4:59     273      83     10    217   30.4%     230    99.9
-    Jul 11 14:50   4:59     273     101      9    199   37.0%     204   100.0
-    Jul 11 14:55   4:59     273      87      7    213   31.9%     223   100.0
-    Jul 11 15:00   4:59     272      99      6    201   36.4%     192    99.9
-    Jul 11 15:05   4:59     273      96     12    204   35.2%     203    99.9
-    Jul 11 15:10   4:59     273      98     12    202   35.9%     182    99.9
-    Jul 11 15:15      1       2       1      0      1   50.0%       1    99.9
+    Jul 11 12:45   4:59     273      84      6    216   30.8%      77    99.1
+    Jul 11 12:50   4:59     272     104      9    196   38.2%     196    98.9
+    Jul 11 12:55   4:59     273     104      4    196   38.1%     188    99.1
+    Jul 11 13:00   4:59     273      92     12    208   33.7%     213    99.3
+    Jul 11 13:05   4:59     273     103      8    197   37.7%     190    99.0
+    Jul 11 13:10   4:59     272     100     16    200   36.8%     203    99.2
+    Jul 11 13:15   4:59     273      91     11    209   33.3%     222    98.7
+    Jul 11 13:20   4:59     273      96      9    204   35.2%     210    99.2
+    Jul 11 13:25   4:59     272      89     11    211   32.7%     212    99.1
+    Jul 11 13:30   4:59     273      82     14    218   30.0%     220    99.1
+    Jul 11 13:35   4:59     273     101      9    199   37.0%     191    99.5
+    Jul 11 13:40   4:59     273      92      6    208   33.7%     214    99.4
+    Jul 11 13:45   4:59     272      80      6    220   29.4%     217    99.3
+    Jul 11 13:50   4:59     273      81      8    219   29.7%     214    99.2
+    Jul 11 13:55   4:59     273      86     11    214   31.5%     208    98.8
+    Jul 11 14:00   4:59     273      95     11    205   34.8%     188    99.3
+    Jul 11 14:05   4:59     272      93     10    207   34.2%     207    99.3
+    Jul 11 14:10   4:59     273     110      6    190   40.3%     198    98.8
+    Jul 11 14:15   4:59     273      91      9    209   33.3%     209    99.1
+    Jul 11 14:20   4:59     272      85     16    215   31.2%     210    99.3
+    Jul 11 14:25   4:59     273      89      8    211   32.6%     226    99.3
+    Jul 11 14:30   4:59     273      96     12    204   35.2%     214    99.3
+    Jul 11 14:35   4:59     273      90     10    210   33.0%     213    99.3
+    Jul 11 14:40   4:59     272     106     10    194   39.0%     196    98.8
+    Jul 11 14:45   4:59     273      80      8    220   29.3%     230    99.0
+    Jul 11 14:50   4:59     273      99      8    201   36.3%     202    99.0
+    Jul 11 14:55   4:59     273      87      8    213   31.9%     205    99.4
+    Jul 11 15:00   4:59     272      98      8    202   36.0%     211    99.3
+    Jul 11 15:05   4:59     273      93     11    207   34.1%     198    99.2
+    Jul 11 15:10   4:59     273      96     11    204   35.2%     184    99.2
+    Jul 11 15:15      1       2       1      0      1   50.0%       1    99.2
     --------------------------------------------------------------------------
-    Jul 11 12:11 3:03:19   10000    3170    327   7830   31.7%    5993    99.9
+    Jul 11 12:45 2:30:01    8184    2794    286   6208   34.1%    6067    99.2
 
     >>> cache_run('cache4', 4)
 
@@ -917,29 +917,29 @@
     Jul 11 13:00-14     818     381      43     519   46.6%
     Jul 11 13:15-29     818     450      44     450   55.0%
     Jul 11 13:30-44     819     503      47     397   61.4%
-    Jul 11 13:45-59     818     501      51     399   61.2%
-    Jul 11 14:00-14     818     523      50     377   63.9%
-    Jul 11 14:15-29     818     528      61     372   64.5%
-    Jul 11 14:30-44     818     509      49     391   62.2%
-    Jul 11 14:45-59     819     522      51     378   63.7%
-    Jul 11 15:00-14     818     504      52     396   61.6%
+    Jul 11 13:45-59     818     496      49     404   60.6%
+    Jul 11 14:00-14     818     516      48     384   63.1%
+    Jul 11 14:15-29     818     532      59     368   65.0%
+    Jul 11 14:30-44     818     516      51     384   63.1%
+    Jul 11 14:45-59     819     529      53     371   64.6%
+    Jul 11 15:00-14     818     515      49     385   63.0%
     Jul 11 15:15-15       2       2       0       0  100.0%
     <BLANKLINE>
-    Read 16,935 trace records (575,782 bytes) in 0.0 seconds
+    Read 16,918 trace records (575,204 bytes) in 0.0 seconds
     Versions:   0 records used a version
     First time: Sun Jul 11 12:11:41 2010
     Last time:  Sun Jul 11 15:15:01 2010
     Duration:   11,000 seconds
-    Data recs:  11,000 (65.0%), average size 1105 bytes
-    Hit rate:   50.7% (load hits / loads)
+    Data recs:  11,000 (65.0%), average size 1104 bytes
+    Hit rate:   50.8% (load hits / loads)
     <BLANKLINE>
             Count Code Function (action)
                 1  00  _setup_trace (initialization)
-              496  10  invalidate (miss)
-              504  1c  invalidate (hit, saving non-current)
-            4,934  20  load (miss)
-            5,066  22  load (hit)
-            5,934  52  store (current, non-version)
+              501  10  invalidate (miss)
+              499  1c  invalidate (hit, saving non-current)
+            4,917  20  load (miss)
+            5,083  22  load (hit)
+            5,917  52  store (current, non-version)
 
     >>> ZEO.scripts.cache_simul.main('-s 4 cache.trace'.split())
     CircularCacheSimulation, cache size 4,194,304 bytes
@@ -950,16 +950,16 @@
     Jul 11 12:45  14:59     818     322     23    578   39.4%       0    61.4
     Jul 11 13:00  14:59     818     381     43    519   46.6%       0    75.8
     Jul 11 13:15  14:59     818     450     44    450   55.0%       0    88.2
-    Jul 11 13:30  14:59     819     503     47    397   61.4%       0    98.9
-    Jul 11 13:45  14:59     818     501     51    399   61.2%     368   100.0
-    Jul 11 14:00  14:59     818     523     50    377   63.9%     372   100.0
-    Jul 11 14:15  14:59     818     528     61    372   64.5%     361   100.0
-    Jul 11 14:30  14:59     818     507     49    393   62.0%     404   100.0
-    Jul 11 14:45  14:59     819     523     51    377   63.9%     387   100.0
-    Jul 11 15:00  14:59     818     503     52    397   61.5%     384   100.0
-    Jul 11 15:15      1       2       2      0      0  100.0%       0   100.0
+    Jul 11 13:30  14:59     819     503     47    397   61.4%      36    98.2
+    Jul 11 13:45  14:59     818     496     49    404   60.6%     388    98.5
+    Jul 11 14:00  14:59     818     515     48    385   63.0%     376    98.3
+    Jul 11 14:15  14:59     818     529     58    371   64.7%     391    98.1
+    Jul 11 14:30  14:59     818     511     51    389   62.5%     376    98.5
+    Jul 11 14:45  14:59     819     529     53    371   64.6%     410    97.9
+    Jul 11 15:00  14:59     818     512     49    388   62.6%     379    97.7
+    Jul 11 15:15      1       2       2      0      0  100.0%       0    97.7
     --------------------------------------------------------------------------
-    Jul 11 12:11 3:03:19   10000    5064    504   5936   50.6%    2276   100.0
+    Jul 11 13:30 1:45:01    5730    3597    355   2705   62.8%    2356    97.7
 
     >>> cache_run('cache1', 1)
 
@@ -969,54 +969,54 @@
     Jul 11 12:11:41 ==================== Restart ====================
     Jul 11 12:11-14     180       1       2     197    0.6%
     Jul 11 12:15-29     818     107       9     793   13.1%
-    Jul 11 12:30-44     818     159      16     741   19.4%
-    Jul 11 12:45-59     818     155       7     745   18.9%
+    Jul 11 12:30-44     818     160      16     740   19.6%
+    Jul 11 12:45-59     818     158       8     742   19.3%
     Jul 11 13:00-14     818     141      21     759   17.2%
     Jul 11 13:15-29     818     128      17     772   15.6%
-    Jul 11 13:30-44     819     152      12     748   18.6%
-    Jul 11 13:45-59     818     121      17     779   14.8%
-    Jul 11 14:00-14     818     157      17     743   19.2%
-    Jul 11 14:15-29     818     149      14     751   18.2%
-    Jul 11 14:30-44     818     159      16     741   19.4%
-    Jul 11 14:45-59     819     140      14     760   17.1%
-    Jul 11 15:00-14     818     155      10     745   18.9%
-    Jul 11 15:15-15       2       0       0       2    0.0%
+    Jul 11 13:30-44     819     151      13     749   18.4%
+    Jul 11 13:45-59     818     120      17     780   14.7%
+    Jul 11 14:00-14     818     159      17     741   19.4%
+    Jul 11 14:15-29     818     141      13     759   17.2%
+    Jul 11 14:30-44     818     157      16     743   19.2%
+    Jul 11 14:45-59     819     133      13     767   16.2%
+    Jul 11 15:00-14     818     158      10     742   19.3%
+    Jul 11 15:15-15       2       1       0       1   50.0%
     <BLANKLINE>
-    Read 20,277 trace records (689,410 bytes) in 0.0 seconds
+    Read 20,286 trace records (689,716 bytes) in 0.0 seconds
     Versions:   0 records used a version
     First time: Sun Jul 11 12:11:41 2010
     Last time:  Sun Jul 11 15:15:01 2010
     Duration:   11,000 seconds
     Data recs:  11,000 (54.2%), average size 1105 bytes
-    Hit rate:   17.2% (load hits / loads)
+    Hit rate:   17.1% (load hits / loads)
     <BLANKLINE>
             Count Code Function (action)
                 1  00  _setup_trace (initialization)
               828  10  invalidate (miss)
               172  1c  invalidate (hit, saving non-current)
-            8,276  20  load (miss)
-            1,724  22  load (hit)
-            9,276  52  store (current, non-version)
+            8,285  20  load (miss)
+            1,715  22  load (hit)
+            9,285  52  store (current, non-version)
 
     >>> ZEO.scripts.cache_simul.main('-s 1 cache.trace'.split())
     CircularCacheSimulation, cache size 1,048,576 bytes
       START TIME   DUR.   LOADS    HITS INVALS WRITES HITRATE  EVICTS   INUSE
     Jul 11 12:11   3:17     180       1      2    197    0.6%       0    21.5
-    Jul 11 12:15  14:59     818     107      9    793   13.1%      94    99.9
-    Jul 11 12:30  14:59     818     159     16    741   19.4%     722    99.9
-    Jul 11 12:45  14:59     818     156      8    744   19.1%     743    99.9
-    Jul 11 13:00  14:59     818     141     21    759   17.2%     767    99.9
-    Jul 11 13:15  14:59     818     126     16    774   15.4%     786    99.9
-    Jul 11 13:30  14:59     819     148     12    752   18.1%     736   100.0
-    Jul 11 13:45  14:59     818     123     17    777   15.0%     764    99.9
-    Jul 11 14:00  14:59     818     158     18    742   19.3%     739   100.0
-    Jul 11 14:15  14:59     818     148     14    752   18.1%     776    99.9
-    Jul 11 14:30  14:59     818     156     15    744   19.1%     745    99.9
-    Jul 11 14:45  14:59     819     142     15    758   17.3%     749    99.9
-    Jul 11 15:00  14:59     818     150     10    750   18.3%     740    99.8
-    Jul 11 15:15      1       2       1      0      1   50.0%       0    99.9
+    Jul 11 12:15  14:59     818     107      9    793   13.1%      96    99.6
+    Jul 11 12:30  14:59     818     160     16    740   19.6%     724    99.6
+    Jul 11 12:45  14:59     818     158      8    742   19.3%     741    99.2
+    Jul 11 13:00  14:59     818     140     21    760   17.1%     771    99.5
+    Jul 11 13:15  14:59     818     125     17    775   15.3%     781    99.6
+    Jul 11 13:30  14:59     819     147     13    753   17.9%     748    99.5
+    Jul 11 13:45  14:59     818     120     17    780   14.7%     763    99.5
+    Jul 11 14:00  14:59     818     159     17    741   19.4%     728    99.4
+    Jul 11 14:15  14:59     818     141     13    759   17.2%     787    99.6
+    Jul 11 14:30  14:59     818     150     15    750   18.3%     755    99.2
+    Jul 11 14:45  14:59     819     132     13    768   16.1%     771    99.5
+    Jul 11 15:00  14:59     818     154     10    746   18.8%     723    99.2
+    Jul 11 15:15      1       2       1      0      1   50.0%       0    99.3
     --------------------------------------------------------------------------
-    Jul 11 12:11 3:03:19   10000    1716    173   9284   17.2%    8361    99.9
+    Jul 11 12:15 3:00:01    9820    1694    169   9108   17.3%    8388    99.3
 
 Cleanup:
 



More information about the Zodb-checkins mailing list