[Zodb-checkins] SVN: ZODB/trunk/src/ Fixed numerous bugs in the ZEO cache tracing and analysys code.
Jim Fulton
jim at zope.com
Mon Jul 12 10:37:41 EDT 2010
Log message for revision 114633:
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.
Changed:
U ZODB/trunk/src/CHANGES.txt
U ZODB/trunk/src/ZEO/cache.py
A ZODB/trunk/src/ZEO/scripts/cache_simul.py
A ZODB/trunk/src/ZEO/scripts/cache_stats.py
U ZODB/trunk/src/ZEO/tests/test_cache.py
D ZODB/trunk/src/ZODB/scripts/simul.py
D ZODB/trunk/src/ZODB/scripts/stats.py
U ZODB/trunk/src/ZODB/tests/util.py
-=-
Modified: ZODB/trunk/src/CHANGES.txt
===================================================================
--- ZODB/trunk/src/CHANGES.txt 2010-07-12 14:37:39 UTC (rev 114632)
+++ ZODB/trunk/src/CHANGES.txt 2010-07-12 14:37:40 UTC (rev 114633)
@@ -26,6 +26,13 @@
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)
=====================
Modified: ZODB/trunk/src/ZEO/cache.py
===================================================================
--- ZODB/trunk/src/ZEO/cache.py 2010-07-12 14:37:39 UTC (rev 114632)
+++ ZODB/trunk/src/ZEO/cache.py 2010-07-12 14:37:40 UTC (rev 114633)
@@ -379,6 +379,7 @@
# 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 @@
# 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 @@
logger.info("opened tracefile %r", tfn)
if _tracefile is None:
- self._trace = lambda *a, **k: None
return
now = time.time
@@ -747,7 +751,7 @@
# 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 @@
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()
Copied: ZODB/trunk/src/ZEO/scripts/cache_simul.py (from rev 114601, ZODB/trunk/src/ZODB/scripts/simul.py)
===================================================================
--- ZODB/trunk/src/ZEO/scripts/cache_simul.py (rev 0)
+++ ZODB/trunk/src/ZEO/scripts/cache_simul.py 2010-07-12 14:37:40 UTC (rev 114633)
@@ -0,0 +1,592 @@
+#! /usr/bin/env python
+##############################################################################
+#
+# Copyright (c) 2001-2005 Zope Foundation and Contributors.
+# All Rights Reserved.
+#
+# This software is subject to the provisions of the Zope Public License,
+# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution.
+# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED
+# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
+# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS
+# FOR A PARTICULAR PURPOSE
+#
+##############################################################################
+"""Cache simulation.
+
+Usage: simul.py [-s size] tracefile
+
+Options:
+-s size: cache size in MB (default 20 MB)
+-i: summarizing interval in minutes (default 15; max 60)
+
+Note:
+
+- The simulation isn't perfect.
+
+- The simulation will be far off if the trace file
+ was created starting with a non-empty cache
+
+
+"""
+
+from sets import Set
+import bisect
+import getopt
+import math
+import struct
+import re
+import sys
+import time
+import ZEO.cache
+
+from ZODB.utils import z64, u64
+
+def usage(msg):
+ print >> sys.stderr, msg
+ print >> sys.stderr, __doc__
+
+def main(args=None):
+ if args is None:
+ args = sys.argv[1:]
+ # Parse options.
+ MB = 1<<20
+ cachelimit = 20*MB
+ simclass = CircularCacheSimulation
+ interval_step = 15
+ try:
+ opts, args = getopt.getopt(args, "s:i:")
+ 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)
+ else:
+ assert False, (o, a)
+
+ interval_step *= 60
+ if interval_step <= 0:
+ interval_step = 60
+ elif interval_step > 3600:
+ interval_step = 3600
+
+ if len(args) != 1:
+ usage("exactly one file argument required")
+ return 2
+ filename = args[0]
+
+ # Open file.
+ if filename.endswith(".gz"):
+ # Open gzipped file.
+ try:
+ import gzip
+ except ImportError:
+ print >> sys.stderr, "can't read gzipped files (no module gzip)"
+ return 1
+ try:
+ f = gzip.open(filename, "rb")
+ except IOError, msg:
+ print >> sys.stderr, "can't open %s: %s" % (filename, msg)
+ return 1
+ elif filename == "-":
+ # Read from stdin.
+ f = sys.stdin
+ else:
+ # Open regular file.
+ try:
+ f = open(filename, "rb")
+ except IOError, msg:
+ print >> sys.stderr, "can't open %s: %s" % (filename, msg)
+ return 1
+
+ # Create simulation object.
+ sim = simclass(cachelimit)
+ interval_sim = simclass(cachelimit)
+
+ # Print output header.
+ sim.printheader()
+
+ # Read trace file, simulating cache behavior.
+ f_read = f.read
+ unpack = struct.unpack
+ FMT = ">iiH8s8s"
+ FMT_SIZE = struct.calcsize(FMT)
+ assert FMT_SIZE == 26
+
+ last_interval = None
+ while 1:
+ # Read a record and decode it.
+ r = f_read(FMT_SIZE)
+ if len(r) < FMT_SIZE:
+ break
+ ts, code, oidlen, start_tid, end_tid = unpack(FMT, r)
+ if ts == 0:
+ # Must be a misaligned record caused by a crash; skip 8 bytes
+ # and try again. Why 8? Lost in the mist of history.
+ f.seek(f.tell() - FMT_SIZE + 8)
+ continue
+ oid = f_read(oidlen)
+ if len(oid) < oidlen:
+ break
+ # Decode the code.
+ dlen, version, code = ((code & 0x7fffff00) >> 8,
+ code & 0x80,
+ code & 0x7e)
+ # And pass it to the simulation.
+ this_interval = int(ts)/interval_step
+ if this_interval != last_interval:
+ if last_interval is not None:
+ interval_sim.report()
+ interval_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)
+
+ f.close()
+ # Finish simulation.
+ interval_sim.report()
+ sim.finish()
+
+class Simulation(object):
+ """Base class for simulations.
+
+ The driver program calls: event(), printheader(), finish().
+
+ The standard event() method calls these additional methods:
+ write(), load(), inval(), report(), restart(); the standard
+ finish() method also calls report().
+ """
+
+ def __init__(self, cachelimit):
+ self.cachelimit = cachelimit
+ # Initialize global statistics.
+ self.epoch = None
+ self.total_loads = 0
+ self.total_hits = 0 # subclass must increment
+ self.total_invals = 0 # subclass must increment
+ self.total_writes = 0
+ if not hasattr(self, "extras"):
+ self.extras = (self.extraname,)
+ self.format = self.format + " %7s" * len(self.extras)
+ # Reset per-run statistics and set up simulation data.
+ self.restart()
+
+ def restart(self):
+ # Reset per-run statistics.
+ self.loads = 0
+ self.hits = 0 # subclass must increment
+ self.invals = 0 # subclass must increment
+ self.writes = 0
+ self.ts0 = None
+
+ def event(self, ts, dlen, _version, code, oid,
+ start_tid, end_tid):
+ # Record first and last timestamp seen.
+ if self.ts0 is None:
+ self.ts0 = ts
+ if self.epoch is None:
+ self.epoch = ts
+ self.ts1 = ts
+
+ # Simulate cache behavior. Caution: the codes in the trace file
+ # record whether the actual cache missed or hit on each load, but
+ # that bears no necessary relationship to whether the simulated cache
+ # will hit or miss. Relatedly, if the actual cache needed to store
+ # an object, the simulated cache may not need to (it may already
+ # have the data).
+ action = code & 0x70
+ if action & 0x20:
+ # Load.
+ self.loads += 1
+ self.total_loads += 1
+ # Asserting that dlen is 0 iff it's a load miss.
+ # assert (dlen == 0) == (code in (0x20, 0x24))
+ self.load(oid, dlen, start_tid, code)
+ elif action & 0x40:
+ # Store.
+ assert dlen
+ self.write(oid, dlen, start_tid, end_tid)
+ elif action & 0x10:
+ # Invalidate.
+ self.inval(oid, start_tid)
+ elif action == 0x00:
+ # Restart.
+ self.restart()
+ else:
+ raise ValueError("unknown trace code 0x%x" % code)
+
+ def write(self, oid, size, start_tid, end_tid):
+ pass
+
+ def load(self, oid, size, start_tid, code):
+ # Must increment .hits and .total_hits as appropriate.
+ pass
+
+ def inval(self, oid, start_tid):
+ # Must increment .invals and .total_invals as appropriate.
+ pass
+
+ format = "%12s %6s %7s %7s %6s %6s %7s"
+
+ # Subclass should override extraname to name known instance variables;
+ # if extraname is 'foo', both self.foo and self.total_foo must exist:
+ extraname = "*** please override ***"
+
+ def printheader(self):
+ print "%s, cache size %s bytes" % (self.__class__.__name__,
+ addcommas(self.cachelimit))
+ self.extraheader()
+ extranames = tuple([s.upper() for s in self.extras])
+ args = ("START TIME", "DUR.", "LOADS", "HITS",
+ "INVALS", "WRITES", "HITRATE") + extranames
+ print self.format % args
+
+ def extraheader(self):
+ pass
+
+ nreports = 0
+
+ def report(self):
+ self.nreports += 1
+ args = (time.ctime(self.ts0)[4:-8],
+ duration(self.ts1 - self.ts0),
+ self.loads, self.hits, self.invals, self.writes,
+ hitrate(self.loads, self.hits))
+ args += tuple([getattr(self, name) for name in self.extras])
+ print self.format % args
+
+ def finish(self):
+ # Make sure that the last line of output ends with "OVERALL". This
+ # makes it much easier for another program parsing the output to
+ # find summary statistics.
+ print '-'*74
+ if self.nreports < 2:
+ self.report()
+ else:
+ self.report()
+ args = (
+ time.ctime(self.epoch)[4:-8],
+ duration(self.ts1 - self.epoch),
+ self.total_loads,
+ self.total_hits,
+ self.total_invals,
+ self.total_writes,
+ hitrate(self.total_loads, self.total_hits))
+ args += tuple([getattr(self, "total_" + name)
+ for name in self.extras])
+ print self.format % args
+
+
+# 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',
+
+ # 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',
+ )
+
+ def __init__(self, key, end_tid, offset):
+ self.key = key
+ self.end_tid = end_tid
+ self.offset = offset
+
+from ZEO.cache import ZEC_HEADER_SIZE
+
+class CircularCacheSimulation(Simulation):
+ """Simulate the ZEO 3.0 cache."""
+
+ # The cache is managed as a single file with a pointer that
+ # goes around the file, circularly, forever. New objects
+ # are written at the current pointer, evicting whatever was
+ # there previously.
+
+ extras = "evicts", "inuse"
+
+ def __init__(self, cachelimit):
+ from ZEO import cache
+
+ Simulation.__init__(self, cachelimit)
+ self.total_evicts = 0 # number of cache evictions
+
+ # Current offset in file.
+ self.offset = ZEC_HEADER_SIZE
+
+ # Map offset in file to (size, CircularCacheEntry) pair, or to
+ # (size, None) if the offset starts a free block.
+ self.filemap = {ZEC_HEADER_SIZE: (self.cachelimit - ZEC_HEADER_SIZE,
+ None)}
+ # Map key to CircularCacheEntry. A key is an (oid, tid) pair.
+ self.key2entry = {}
+
+ # Map oid to tid of current revision.
+ self.current = {}
+
+ # Map oid to list of (start_tid, end_tid) pairs in sorted order.
+ # Used to find matching key for load of non-current data.
+ self.noncurrent = {}
+
+ # The number of overhead bytes needed to store an object pickle
+ # on disk (all bytes beyond those needed for the object pickle).
+ self.overhead = ZEO.cache.allocated_record_overhead
+
+ # save evictions so we can replay them, if necessary
+ self.evicted = {}
+
+ def restart(self):
+ Simulation.restart(self)
+ self.evicts = 0
+ self.evicted_hit = self.evicted_miss = 0
+
+ evicted_hit = evicted_miss = 0
+ def load(self, oid, size, tid, code):
+ if (code == 0x20) or (code == 0x22):
+ # Trying to load current revision.
+ if oid in self.current: # else it's a cache miss
+ self.hits += 1
+ self.total_hits += 1
+ elif oid in self.evicted:
+ size, e = self.evicted[oid]
+ self.write(oid, size, e.key[1], z64, 1)
+ self.evicted_hit += 1
+ else:
+ self.evicted_miss += 1
+
+ return
+
+ # May or may not be trying to load current revision.
+ cur_tid = self.current.get(oid)
+ if cur_tid == tid:
+ self.hits += 1
+ self.total_hits += 1
+ return
+
+ # It's a load for non-current data. Do we know about this oid?
+ L = self.noncurrent.get(oid)
+ if L is None:
+ return # cache miss
+ i = bisect.bisect_left(L, (tid, None))
+ if i == 0:
+ # This tid is smaller than any we know about -- miss.
+ return
+ lo, hi = L[i-1]
+ assert lo < tid
+ if tid > hi:
+ # No data in the right tid range -- miss.
+ return
+ # Cache hit.
+ self.hits += 1
+ self.total_hits += 1
+
+ # (oid, tid) is in the cache. Remove it: take it out of key2entry,
+ # and in `filemap` mark the space it occupied as being free. The
+ # caller is responsible for removing it from `current` or `noncurrent`.
+ def _remove(self, oid, tid):
+ key = oid, tid
+ e = self.key2entry.pop(key)
+ pos = e.offset
+ size, _e = self.filemap[pos]
+ assert e is _e
+ self.filemap[pos] = size, None
+
+ def _remove_noncurrent_revisions(self, oid):
+ noncurrent_list = self.noncurrent.get(oid)
+ if noncurrent_list:
+ self.invals += len(noncurrent_list)
+ self.total_invals += len(noncurrent_list)
+ for start_tid, end_tid in noncurrent_list:
+ self._remove(oid, start_tid)
+ del self.noncurrent[oid]
+
+ def inval(self, oid, tid):
+ if tid == z64:
+ # This is part of startup cache verification: forget everything
+ # about this oid.
+ self._remove_noncurrent_revisions(oid)
+
+ cur_tid = self.current.get(oid)
+ if cur_tid is None:
+ # We don't have current data, so nothing more to do.
+ return
+
+ # We had current data for oid, but no longer.
+ self.invals += 1
+ self.total_invals += 1
+ del self.current[oid]
+ if tid == z64:
+ # Startup cache verification: forget this oid entirely.
+ self._remove(oid, cur_tid)
+ return
+
+ # Our current data becomes non-current data.
+ # Add the validity range to the list of non-current data for oid.
+ assert cur_tid < tid
+ L = self.noncurrent.setdefault(oid, [])
+ bisect.insort_left(L, (cur_tid, tid))
+ # Update the end of oid's validity range in its CircularCacheEntry.
+ e = self.key2entry[oid, cur_tid]
+ assert e.end_tid == z64
+ e.end_tid = tid
+
+ def write(self, oid, size, start_tid, end_tid, evhit=0):
+ if end_tid == z64:
+ # Storing current revision.
+ if oid in self.current: # we already have it in cache
+ if evhit:
+ import pdb; pdb.set_trace()
+ raise ValueError('WTF')
+ return
+ self.current[oid] = start_tid
+ self.writes += 1
+ self.total_writes += 1
+ self.add(oid, size, start_tid)
+ return
+ if evhit:
+ import pdb; pdb.set_trace()
+ raise ValueError('WTF')
+ # Storing non-current revision.
+ L = self.noncurrent.setdefault(oid, [])
+ p = start_tid, end_tid
+ if p in L:
+ return # we already have it in cache
+ bisect.insort_left(L, p)
+ self.writes += 1
+ self.total_writes += 1
+ self.add(oid, size, start_tid, end_tid)
+
+ # Add `oid` to the cache, evicting objects as needed to make room.
+ # This updates `filemap` and `key2entry`; it's the caller's
+ # responsibilty to update `current` or `noncurrent` appropriately.
+ def add(self, oid, size, start_tid, end_tid=z64):
+ key = oid, start_tid
+ assert key not in self.key2entry
+ size += self.overhead
+ avail = self.makeroom(size+1) # see cache.py
+ e = CircularCacheEntry(key, end_tid, self.offset)
+ self.filemap[self.offset] = size, e
+ self.key2entry[key] = e
+ self.offset += size
+ # All the space made available must be accounted for in filemap.
+ excess = avail - size
+ if excess:
+ self.filemap[self.offset] = excess, None
+
+ # Evict enough objects to make at least `need` contiguous bytes, starting
+ # at `self.offset`, available. Evicted objects are removed from
+ # `filemap`, `key2entry`, `current` and `noncurrent`. The caller is
+ # responsible for adding new entries to `filemap` to account for all
+ # the freed bytes, and for advancing `self.offset`. The number of bytes
+ # freed is the return value, and will be >= need.
+ def makeroom(self, need):
+ if self.offset + need > self.cachelimit:
+ self.offset = ZEC_HEADER_SIZE
+ pos = self.offset
+ while need > 0:
+ assert pos < self.cachelimit
+ size, e = self.filemap.pop(pos)
+ if e: # there is an object here (else it's already free space)
+ self.evicts += 1
+ self.total_evicts += 1
+ assert pos == e.offset
+ _e = self.key2entry.pop(e.key)
+ assert e is _e
+ oid, start_tid = e.key
+ if e.end_tid == z64:
+ del self.current[oid]
+ self.evicted[oid] = size-self.overhead, e
+ else:
+ L = self.noncurrent[oid]
+ L.remove((start_tid, e.end_tid))
+ need -= size
+ pos += size
+ return pos - self.offset # total number of bytes freed
+
+ def report(self):
+ self.check()
+ free = used = total = 0
+ for size, e in self.filemap.itervalues():
+ total += size
+ if e:
+ used += size
+ else:
+ free += size
+
+ self.inuse = round(100.0 * used / total, 1)
+ self.total_inuse = self.inuse
+ Simulation.report(self)
+ #print self.evicted_hit, self.evicted_miss
+
+ def check(self):
+ oidcount = 0
+ pos = ZEC_HEADER_SIZE
+ while pos < self.cachelimit:
+ size, e = self.filemap[pos]
+ if e:
+ oidcount += 1
+ assert self.key2entry[e.key].offset == pos
+ pos += size
+ assert oidcount == len(self.key2entry)
+ assert pos == self.cachelimit
+
+ def dump(self):
+ print len(self.filemap)
+ L = list(self.filemap)
+ L.sort()
+ for k in L:
+ v = self.filemap[k]
+ print k, v[0], repr(v[1])
+
+
+def roundup(size):
+ k = MINSIZE
+ while k < size:
+ k += k
+ return k
+
+def hitrate(loads, hits):
+ if loads < 1:
+ return 'n/a'
+ return "%5.1f%%" % (100.0 * hits / loads)
+
+def duration(secs):
+ mm, ss = divmod(secs, 60)
+ hh, mm = divmod(mm, 60)
+ if hh:
+ return "%d:%02d:%02d" % (hh, mm, ss)
+ if mm:
+ return "%d:%02d" % (mm, ss)
+ return "%d" % ss
+
+nre = re.compile('([=-]?)(\d+)([.]\d*)?').match
+def addcommas(n):
+ sign, s, d = nre(str(n)).group(1, 2, 3)
+ if d == '.0':
+ d = ''
+
+ result = s[-3:]
+ s = s[:-3]
+ while s:
+ result = s[-3:]+','+result
+ s = s[:-3]
+
+ return (sign or '') + result + (d or '')
+
+import random
+
+def maybe(f, p=0.5):
+ if random.random() < p:
+ f()
+
+if __name__ == "__main__":
+ sys.exit(main())
Copied: ZODB/trunk/src/ZEO/scripts/cache_stats.py (from rev 114601, ZODB/trunk/src/ZODB/scripts/stats.py)
===================================================================
--- ZODB/trunk/src/ZEO/scripts/cache_stats.py (rev 0)
+++ ZODB/trunk/src/ZEO/scripts/cache_stats.py 2010-07-12 14:37:40 UTC (rev 114633)
@@ -0,0 +1,396 @@
+##############################################################################
+#
+# Copyright (c) 2001, 2002 Zope Foundation and Contributors.
+# All Rights Reserved.
+#
+# This software is subject to the provisions of the Zope Public License,
+# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution.
+# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED
+# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
+# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS
+# FOR A PARTICULAR PURPOSE
+#
+##############################################################################
+"""Trace file statistics analyzer.
+
+Usage: stats.py [-h] [-i interval] [-q] [-s] [-S] [-v] [-X] tracefile
+-h: print histogram of object load frequencies
+-i: summarizing interval in minutes (default 15; max 60)
+-q: quiet; don't print summaries
+-s: print histogram of object sizes
+-S: don't print statistics
+-v: verbose; print each record
+-X: enable heuristic checking for misaligned records: oids > 2**32
+ will be rejected; this requires the tracefile to be seekable
+"""
+
+"""File format:
+
+Each record is 26 bytes, plus a variable number of bytes to store an oid,
+with the following layout. Numbers are big-endian integers.
+
+Offset Size Contents
+
+0 4 timestamp (seconds since 1/1/1970)
+4 3 data size, in 256-byte increments, rounded up
+7 1 code (see below)
+8 2 object id length
+10 8 start tid
+18 8 end tid
+26 variable object id
+
+The code at offset 7 packs three fields:
+
+Mask bits Contents
+
+0x80 1 set if there was a non-empty version string
+0x7e 6 function and outcome code
+0x01 1 current cache file (0 or 1)
+
+The "current cache file" bit is no longer used; it refers to a 2-file
+cache scheme used before ZODB 3.3.
+
+The function and outcome codes are documented in detail at the end of
+this file in the 'explain' dictionary. Note that the keys there (and
+also the arguments to _trace() in ClientStorage.py) are 'code & 0x7e',
+i.e. the low bit is always zero.
+"""
+
+import sys
+import time
+import getopt
+import struct
+from types import StringType
+
+def usage(msg):
+ print >> sys.stderr, msg
+ print >> sys.stderr, __doc__
+
+def main(args=None):
+ if args is None:
+ args = sys.argv[1:]
+ # Parse options
+ verbose = False
+ quiet = False
+ dostats = True
+ print_size_histogram = False
+ print_histogram = False
+ interval = 15*60 # Every 15 minutes
+ heuristic = False
+ try:
+ opts, args = getopt.getopt(args, "hi:qsSvX")
+ except getopt.error, msg:
+ usage(msg)
+ return 2
+ for o, a in opts:
+ if o == '-h':
+ print_histogram = True
+ elif o == "-i":
+ interval = int(60 * float(a))
+ if interval <= 0:
+ interval = 60
+ elif interval > 3600:
+ interval = 3600
+ elif o == "-q":
+ quiet = True
+ verbose = False
+ elif o == "-s":
+ print_size_histogram = True
+ elif o == "-S":
+ dostats = False
+ elif o == "-v":
+ verbose = True
+ elif o == '-X':
+ heuristic = True
+ else:
+ assert False, (o, opts)
+
+ if len(args) != 1:
+ usage("exactly one file argument required")
+ return 2
+ filename = args[0]
+
+ # Open file
+ if filename.endswith(".gz"):
+ # Open gzipped file
+ try:
+ import gzip
+ except ImportError:
+ print >> sys.stderr, "can't read gzipped files (no module gzip)"
+ return 1
+ try:
+ f = gzip.open(filename, "rb")
+ except IOError, msg:
+ print >> sys.stderr, "can't open %s: %s" % (filename, msg)
+ return 1
+ elif filename == '-':
+ # Read from stdin
+ f = sys.stdin
+ else:
+ # Open regular file
+ try:
+ f = open(filename, "rb")
+ except IOError, msg:
+ print >> sys.stderr, "can't open %s: %s" % (filename, msg)
+ return 1
+
+ rt0 = time.time()
+ bycode = {} # map code to count of occurrences
+ byinterval = {} # map code to count in current interval
+ records = 0 # number of trace records read
+ versions = 0 # number of trace records with versions
+ datarecords = 0 # number of records with dlen set
+ datasize = 0L # sum of dlen across records with dlen set
+ oids = {} # map oid to number of times it was loaded
+ bysize = {} # map data size to number of loads
+ bysizew = {} # map data size to number of writes
+ total_loads = 0
+ t0 = None # first timestamp seen
+ te = None # most recent timestamp seen
+ h0 = None # timestamp at start of current interval
+ he = None # timestamp at end of current interval
+ thisinterval = None # generally te//interval
+ f_read = f.read
+ unpack = struct.unpack
+ FMT = ">iiH8s8s"
+ 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)
+ if len(r) < FMT_SIZE:
+ break
+ ts, code, oidlen, start_tid, end_tid = unpack(FMT, r)
+ if ts == 0:
+ # Must be a misaligned record caused by a crash.
+ if not quiet:
+ print "Skipping 8 bytes at offset", f.tell() - FMT_SIZE
+ f.seek(f.tell() - FMT_SIZE + 8)
+ continue
+ oid = f_read(oidlen)
+ if len(oid) < oidlen:
+ break
+ records += 1
+ if t0 is None:
+ t0 = ts
+ thisinterval = t0 // interval
+ h0 = he = ts
+ te = ts
+ if ts // interval != thisinterval:
+ if not quiet:
+ dumpbyinterval(byinterval, h0, he)
+ byinterval = {}
+ thisinterval = ts // interval
+ h0 = ts
+ he = ts
+ dlen, code = (code & 0x7fffff00) >> 8, code & 0xff
+ if dlen:
+ datarecords += 1
+ datasize += dlen
+ if code & 0x80:
+ version = 'V'
+ versions += 1
+ else:
+ version = '-'
+ code &= 0x7e
+ bycode[code] = bycode.get(code, 0) + 1
+ byinterval[code] = byinterval.get(code, 0) + 1
+ if dlen:
+ if code & 0x70 == 0x20: # All loads
+ bysize[dlen] = d = bysize.get(dlen) or {}
+ d[oid] = d.get(oid, 0) + 1
+ elif code & 0x70 == 0x50: # All stores
+ bysizew[dlen] = d = bysizew.get(dlen) or {}
+ d[oid] = d.get(oid, 0) + 1
+ if verbose:
+ print "%s %02x %s %016x %016x %c %s" % (
+ time.ctime(ts)[4:-5],
+ code,
+ oid_repr(oid),
+ U64(start_tid),
+ U64(end_tid),
+ version,
+ dlen and str(dlen) or "")
+ if code & 0x70 == 0x20:
+ oids[oid] = oids.get(oid, 0) + 1
+ total_loads += 1
+ elif code == 0x00: # restart
+ if not quiet:
+ dumpbyinterval(byinterval, h0, he)
+ byinterval = {}
+ thisinterval = ts // interval
+ h0 = he = ts
+ if not quiet:
+ print time.ctime(ts)[4:-5],
+ print '='*20, "Restart", '='*20
+ except KeyboardInterrupt:
+ print "\nInterrupted. Stats so far:\n"
+
+ end_pos = f.tell()
+ f.close()
+ rte = time.time()
+ if not quiet:
+ dumpbyinterval(byinterval, h0, he)
+
+ # Error if nothing was read
+ if not records:
+ print >> sys.stderr, "No records processed"
+ return 1
+
+ # Print statistics
+ if dostats:
+ print
+ print "Read %s trace records (%s bytes) in %.1f seconds" % (
+ addcommas(records), addcommas(end_pos), rte-rt0)
+ print "Versions: %s records used a version" % addcommas(versions)
+ 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 %d bytes" % (
+ addcommas(datarecords),
+ 100.0 * datarecords / records,
+ datasize / datarecords)
+ print "Hit rate: %.1f%% (load hits / loads)" % hitrate(bycode)
+ print
+ codes = bycode.keys()
+ codes.sort()
+ print "%13s %4s %s" % ("Count", "Code", "Function (action)")
+ for code in codes:
+ print "%13s %02x %s" % (
+ addcommas(bycode.get(code, 0)),
+ code,
+ explain.get(code) or "*** unknown code ***")
+
+ # Print histogram.
+ if print_histogram:
+ print
+ print "Histogram of object load frequency"
+ total = len(oids)
+ print "Unique oids: %s" % addcommas(total)
+ print "Total loads: %s" % addcommas(total_loads)
+ s = addcommas(total)
+ width = max(len(s), len("objects"))
+ fmt = "%5d %" + str(width) + "s %5.1f%% %5.1f%% %5.1f%%"
+ hdr = "%5s %" + str(width) + "s %6s %6s %6s"
+ print hdr % ("loads", "objects", "%obj", "%load", "%cum")
+ cum = 0.0
+ for binsize, count in histogram(oids):
+ obj_percent = 100.0 * count / total
+ load_percent = 100.0 * count * binsize / total_loads
+ cum += load_percent
+ print fmt % (binsize, addcommas(count),
+ obj_percent, load_percent, cum)
+
+ # Print size histogram.
+ if print_size_histogram:
+ print
+ print "Histograms of object sizes"
+ print
+ dumpbysize(bysizew, "written", "writes")
+ dumpbysize(bysize, "loaded", "loads")
+
+def dumpbysize(bysize, how, how2):
+ print
+ print "Unique sizes %s: %s" % (how, addcommas(len(bysize)))
+ print "%10s %6s %6s" % ("size", "objs", how2)
+ sizes = bysize.keys()
+ sizes.sort()
+ for size in sizes:
+ loads = 0
+ for n in bysize[size].itervalues():
+ loads += n
+ print "%10s %6d %6d" % (addcommas(size),
+ len(bysize.get(size, "")),
+ loads)
+
+def dumpbyinterval(byinterval, h0, he):
+ loads = hits = invals = writes = 0
+ for code in byinterval:
+ if code & 0x20:
+ n = byinterval[code]
+ loads += n
+ if code in (0x22, 0x26):
+ hits += n
+ elif code & 0x40:
+ writes += byinterval[code]
+ elif code & 0x10:
+ if code != 0x10:
+ invals += byinterval[code]
+
+ if loads:
+ hr = "%5.1f%%" % (100.0 * hits / loads)
+ else:
+ hr = 'n/a'
+
+ print "%s-%s %7s %7s %7s %7s %7s" % (
+ time.ctime(h0)[4:-8], time.ctime(he)[14:-8],
+ loads, hits, invals, writes, hr)
+
+def hitrate(bycode):
+ loads = hits = 0
+ for code in bycode:
+ if code & 0x70 == 0x20:
+ n = bycode[code]
+ loads += n
+ if code in (0x22, 0x26):
+ hits += n
+ if loads:
+ return 100.0 * hits / loads
+ else:
+ return 0.0
+
+def histogram(d):
+ bins = {}
+ for v in d.itervalues():
+ bins[v] = bins.get(v, 0) + 1
+ L = bins.items()
+ L.sort()
+ return L
+
+def U64(s):
+ return struct.unpack(">Q", s)[0]
+
+def oid_repr(oid):
+ if isinstance(oid, StringType) and len(oid) == 8:
+ return '%16x' % U64(oid)
+ else:
+ return repr(oid)
+
+def addcommas(n):
+ sign, s = '', str(n)
+ if s[0] == '-':
+ sign, s = '-', s[1:]
+ i = len(s) - 3
+ while i > 0:
+ s = s[:i] + ',' + s[i:]
+ i -= 3
+ return sign + s
+
+explain = {
+ # The first hex digit shows the operation, the second the outcome.
+ # If the second digit is in "02468" then it is a 'miss'.
+ # If it is in "ACE" then it is a 'hit'.
+
+ 0x00: "_setup_trace (initialization)",
+
+ 0x10: "invalidate (miss)",
+ 0x1A: "invalidate (hit, version)",
+ 0x1C: "invalidate (hit, saving non-current)",
+ # 0x1E can occur during startup verification.
+ 0x1E: "invalidate (hit, discarding current or non-current)",
+
+ 0x20: "load (miss)",
+ 0x22: "load (hit)",
+ 0x24: "load (non-current, miss)",
+ 0x26: "load (non-current, hit)",
+
+ 0x50: "store (version)",
+ 0x52: "store (current, non-version)",
+ 0x54: "store (non-current)",
+ }
+
+if __name__ == "__main__":
+ sys.exit(main())
Modified: ZODB/trunk/src/ZEO/tests/test_cache.py
===================================================================
--- ZODB/trunk/src/ZEO/tests/test_cache.py 2010-07-12 14:37:39 UTC (rev 114632)
+++ ZODB/trunk/src/ZEO/tests/test_cache.py 2010-07-12 14:37:40 UTC (rev 114633)
@@ -248,7 +248,7 @@
self.assertEqual(len(cache), 0)
self.assertEqual(cache.load(n3), None)
self.assertEqual(cache.loadBefore(n3, n2), None)
-
+
def testChangingCacheSize(self):
# start with a small cache
data = 'x'
@@ -309,7 +309,7 @@
for i in range(200, 305):
cache.store(p64(i), n1, None, data)
-
+
# We use large-2 for the same reason we used small-1 above.
expected_len = large-2
self.assertEquals(len(cache), expected_len)
@@ -335,170 +335,696 @@
self.cache.setLastTid(p64(3))
self.cache.setLastTid(p64(4))
-__test__ = dict(
- kill_does_not_cause_cache_corruption =
+def kill_does_not_cause_cache_corruption():
r"""
- If we kill a process while a cache is being written to, the cache
- isn't corrupted. To see this, we'll write a little script that
- writes records to a cache file repeatedly.
+If we kill a process while a cache is being written to, the cache
+isn't corrupted. To see this, we'll write a little script that
+writes records to a cache file repeatedly.
- >>> import os, random, sys, time
- >>> open('t', 'w').write('''
- ... import os, random, sys, thread, time
- ... sys.path = %r
- ...
- ... def suicide():
- ... time.sleep(random.random()/10)
- ... os._exit(0)
- ...
- ... import ZEO.cache
- ... from ZODB.utils import p64
- ... cache = ZEO.cache.ClientCache('cache')
- ... oid = 0
- ... t = 0
- ... thread.start_new_thread(suicide, ())
- ... while 1:
- ... oid += 1
- ... t += 1
- ... data = 'X' * random.randint(5000,25000)
- ... cache.store(p64(oid), p64(t), None, data)
- ...
- ... ''' % sys.path)
+>>> import os, random, sys, time
+>>> open('t', 'w').write('''
+... import os, random, sys, thread, time
+... sys.path = %r
+...
+... def suicide():
+... time.sleep(random.random()/10)
+... os._exit(0)
+...
+... import ZEO.cache
+... from ZODB.utils import p64
+... cache = ZEO.cache.ClientCache('cache')
+... oid = 0
+... t = 0
+... thread.start_new_thread(suicide, ())
+... while 1:
+... oid += 1
+... t += 1
+... data = 'X' * random.randint(5000,25000)
+... cache.store(p64(oid), p64(t), None, data)
+...
+... ''' % sys.path)
- >>> for i in range(10):
- ... _ = os.spawnl(os.P_WAIT, sys.executable, sys.executable, 't')
- ... if os.path.exists('cache'):
- ... cache = ZEO.cache.ClientCache('cache')
- ... cache.close()
- ... os.remove('cache')
- ... os.remove('cache.lock')
-
-
- """,
+>>> for i in range(10):
+... _ = os.spawnl(os.P_WAIT, sys.executable, sys.executable, 't')
+... if os.path.exists('cache'):
+... cache = ZEO.cache.ClientCache('cache')
+... cache.close()
+... os.remove('cache')
+... os.remove('cache.lock')
- full_cache_is_valid =
+
+"""
+
+def full_cache_is_valid():
r"""
- If we fill up the cache without any free space, the cache can
- still be used.
+If we fill up the cache without any free space, the cache can
+still be used.
- >>> import ZEO.cache
- >>> cache = ZEO.cache.ClientCache('cache', 1000)
- >>> data = 'X' * (1000 - ZEO.cache.ZEC_HEADER_SIZE - 41)
- >>> cache.store(p64(1), p64(1), None, data)
- >>> cache.close()
- >>> cache = ZEO.cache.ClientCache('cache', 1000)
- >>> cache.store(p64(2), p64(2), None, 'XXX')
+>>> import ZEO.cache
+>>> cache = ZEO.cache.ClientCache('cache', 1000)
+>>> data = 'X' * (1000 - ZEO.cache.ZEC_HEADER_SIZE - 41)
+>>> cache.store(p64(1), p64(1), None, data)
+>>> cache.close()
+>>> cache = ZEO.cache.ClientCache('cache', 1000)
+>>> cache.store(p64(2), p64(2), None, 'XXX')
- >>> cache.close()
- """,
+>>> cache.close()
+"""
- cannot_open_same_cache_file_twice =
+def cannot_open_same_cache_file_twice():
r"""
- >>> import ZEO.cache
- >>> cache = ZEO.cache.ClientCache('cache', 1000)
- >>> cache2 = ZEO.cache.ClientCache('cache', 1000)
- Traceback (most recent call last):
- ...
- LockError: Couldn't lock 'cache.lock'
+>>> import ZEO.cache
+>>> cache = ZEO.cache.ClientCache('cache', 1000)
+>>> cache2 = ZEO.cache.ClientCache('cache', 1000)
+Traceback (most recent call last):
+...
+LockError: Couldn't lock 'cache.lock'
- >>> cache.close()
- """,
+>>> cache.close()
+"""
- thread_safe =
+def thread_safe():
r"""
- >>> import ZEO.cache, ZODB.utils
- >>> cache = ZEO.cache.ClientCache('cache', 1000000)
+>>> import ZEO.cache, ZODB.utils
+>>> cache = ZEO.cache.ClientCache('cache', 1000000)
- >>> for i in range(100):
- ... cache.store(ZODB.utils.p64(i), ZODB.utils.p64(1), None, '0')
+>>> for i in range(100):
+... cache.store(ZODB.utils.p64(i), ZODB.utils.p64(1), None, '0')
- >>> import random, sys, threading
- >>> random = random.Random(0)
- >>> stop = False
- >>> read_failure = None
+>>> import random, sys, threading
+>>> random = random.Random(0)
+>>> stop = False
+>>> read_failure = None
- >>> def read_thread():
- ... def pick_oid():
- ... return ZODB.utils.p64(random.randint(0,99))
- ...
- ... try:
- ... while not stop:
- ... cache.load(pick_oid())
- ... cache.loadBefore(pick_oid(), ZODB.utils.p64(2))
- ... except:
- ... global read_failure
- ... read_failure = sys.exc_info()
+>>> def read_thread():
+... def pick_oid():
+... return ZODB.utils.p64(random.randint(0,99))
+...
+... try:
+... while not stop:
+... cache.load(pick_oid())
+... cache.loadBefore(pick_oid(), ZODB.utils.p64(2))
+... except:
+... global read_failure
+... read_failure = sys.exc_info()
- >>> thread = threading.Thread(target=read_thread)
- >>> thread.start()
+>>> thread = threading.Thread(target=read_thread)
+>>> thread.start()
- >>> for tid in range(2,10):
- ... for oid in range(100):
- ... oid = ZODB.utils.p64(oid)
- ... cache.invalidate(oid, ZODB.utils.p64(tid))
- ... cache.store(oid, ZODB.utils.p64(tid), None, str(tid))
+>>> for tid in range(2,10):
+... for oid in range(100):
+... oid = ZODB.utils.p64(oid)
+... cache.invalidate(oid, ZODB.utils.p64(tid))
+... cache.store(oid, ZODB.utils.p64(tid), None, str(tid))
- >>> stop = True
- >>> thread.join()
- >>> if read_failure:
- ... print 'Read failure:'
- ... import traceback
- ... traceback.print_exception(*read_failure)
+>>> stop = True
+>>> thread.join()
+>>> if read_failure:
+... print 'Read failure:'
+... import traceback
+... traceback.print_exception(*read_failure)
- >>> expected = '9', ZODB.utils.p64(9)
- >>> for oid in range(100):
- ... loaded = cache.load(ZODB.utils.p64(oid))
- ... if loaded != expected:
- ... print oid, loaded
+>>> expected = '9', ZODB.utils.p64(9)
+>>> for oid in range(100):
+... loaded = cache.load(ZODB.utils.p64(oid))
+... if loaded != expected:
+... print oid, loaded
- >>> cache.close()
-
- """,
+>>> cache.close()
- broken_non_current =
+"""
+
+def broken_non_current():
r"""
- In production, we saw a situation where an _del_noncurrent raused
- a key error when trying to free space, causing the cache to become
- unusable. I can't see why this would occur, but added a logging
- exception handler so, in the future, we'll still see cases in the
- log, but will ignore the error and keep going.
-
- >>> import ZEO.cache, ZODB.utils, logging, sys
- >>> logger = logging.getLogger('ZEO.cache')
- >>> logger.setLevel(logging.ERROR)
- >>> handler = logging.StreamHandler(sys.stdout)
- >>> logger.addHandler(handler)
- >>> cache = ZEO.cache.ClientCache('cache', 1000)
- >>> cache.store(ZODB.utils.p64(1), ZODB.utils.p64(1), None, '0')
- >>> cache.invalidate(ZODB.utils.p64(1), ZODB.utils.p64(2))
- >>> cache._del_noncurrent(ZODB.utils.p64(1), ZODB.utils.p64(2))
- ... # doctest: +NORMALIZE_WHITESPACE
- Couldn't find non-current
- ('\x00\x00\x00\x00\x00\x00\x00\x01', '\x00\x00\x00\x00\x00\x00\x00\x02')
- >>> cache._del_noncurrent(ZODB.utils.p64(1), ZODB.utils.p64(1))
- >>> cache._del_noncurrent(ZODB.utils.p64(1), ZODB.utils.p64(1)) #
- ... # doctest: +NORMALIZE_WHITESPACE
- Couldn't find non-current
- ('\x00\x00\x00\x00\x00\x00\x00\x01', '\x00\x00\x00\x00\x00\x00\x00\x01')
+In production, we saw a situation where an _del_noncurrent raused
+a key error when trying to free space, causing the cache to become
+unusable. I can't see why this would occur, but added a logging
+exception handler so, in the future, we'll still see cases in the
+log, but will ignore the error and keep going.
- >>> logger.setLevel(logging.NOTSET)
- >>> logger.removeHandler(handler)
+>>> import ZEO.cache, ZODB.utils, logging, sys
+>>> logger = logging.getLogger('ZEO.cache')
+>>> logger.setLevel(logging.ERROR)
+>>> handler = logging.StreamHandler(sys.stdout)
+>>> logger.addHandler(handler)
+>>> cache = ZEO.cache.ClientCache('cache', 1000)
+>>> cache.store(ZODB.utils.p64(1), ZODB.utils.p64(1), None, '0')
+>>> cache.invalidate(ZODB.utils.p64(1), ZODB.utils.p64(2))
+>>> cache._del_noncurrent(ZODB.utils.p64(1), ZODB.utils.p64(2))
+... # doctest: +NORMALIZE_WHITESPACE
+Couldn't find non-current
+('\x00\x00\x00\x00\x00\x00\x00\x01', '\x00\x00\x00\x00\x00\x00\x00\x02')
+>>> cache._del_noncurrent(ZODB.utils.p64(1), ZODB.utils.p64(1))
+>>> cache._del_noncurrent(ZODB.utils.p64(1), ZODB.utils.p64(1)) #
+... # doctest: +NORMALIZE_WHITESPACE
+Couldn't find non-current
+('\x00\x00\x00\x00\x00\x00\x00\x01', '\x00\x00\x00\x00\x00\x00\x00\x01')
- >>> cache.close()
- """,
- bad_magic_number =
+>>> logger.setLevel(logging.NOTSET)
+>>> logger.removeHandler(handler)
+
+>>> cache.close()
+"""
+
+def bad_magic_number():
r"""
- >>> open('cache', 'w').write("Hi world!")
- >>> try: cache = ZEO.cache.ClientCache('cache', 1000)
- ... except Exception, v: print v
- unexpected magic number: 'Hi w'
- """
- )
+>>> open('cache', 'w').write("Hi world!")
+>>> try: cache = ZEO.cache.ClientCache('cache', 1000)
+... except Exception, v: print v
+unexpected magic number: 'Hi w'
+"""
+def cache_trace_analysis():
+ r"""
+Check to make sure the cache analysis scripts work.
+
+ >>> import time
+ >>> timetime = time.time
+ >>> now = 1278864701.5
+ >>> time.time = lambda : now
+
+ >>> os.environ["ZEO_CACHE_TRACE"] = 'yes'
+ >>> import random
+ >>> random = random.Random(42)
+ >>> history = []
+ >>> serial = 1
+ >>> for i in range(1000):
+ ... serial += 1
+ ... oid = random.randint(i+1000, i+6000)
+ ... history.append(('s', p64(oid), p64(serial),
+ ... 'x'*random.randint(200,2000)))
+ ... for j in range(10):
+ ... oid = random.randint(i+1000, i+6000)
+ ... history.append(('l', p64(oid), p64(serial),
+ ... 'x'*random.randint(200,2000)))
+
+ >>> def cache_run(name, size):
+ ... serial = 1
+ ... random.seed(42)
+ ... global now
+ ... now = 1278864701.5
+ ... cache = ZEO.cache.ClientCache(name, size*(1<<20))
+ ... for action, oid, serial, data in history:
+ ... now += 1
+ ... if action == 's':
+ ... cache.invalidate(oid, serial)
+ ... cache.store(oid, serial, None, data)
+ ... else:
+ ... v = cache.load(oid)
+ ... if v is None:
+ ... cache.store(oid, serial, None, data)
+ ... cache.close()
+
+ >>> cache_run('cache', 2)
+
+ >>> import ZEO.scripts.cache_stats, ZEO.scripts.cache_simul
+
+ ############################################################
+ Stats
+
+ >>> ZEO.scripts.cache_stats.main(['cache.trace'])
+ loads hits inv(h) writes hitrate
+ Jul 11 12:11-11 0 0 0 0 n/a
+ 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 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 15:15-15 2 1 0 1 50.0%
+ <BLANKLINE>
+ Read 18,837 trace records (640,450 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)
+ <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)
+
+ >>> 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
+ 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)
+ <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)
+
+ >>> ZEO.scripts.cache_stats.main('-v cache.trace'.split())
+ ... # doctest: +ELLIPSIS
+ loads hits inv(h) writes hitrate
+ Jul 11 12:11:41 00 '' 0000000000000000 0000000000000000 -
+ Jul 11 12:11-11 0 0 0 0 n/a
+ Jul 11 12:11:41 ==================== Restart ====================
+ Jul 11 12:11:42 10 1065 0000000000000002 0000000000000000 -
+ Jul 11 12:11:42 52 1065 0000000000000002 0000000000000000 - 245
+ Jul 11 12:11:43 20 947 0000000000000000 0000000000000000 -
+ Jul 11 12:11:43 52 947 0000000000000002 0000000000000000 - 602
+ Jul 11 12:11:44 20 124b 0000000000000000 0000000000000000 -
+ Jul 11 12:11:44 52 124b 0000000000000002 0000000000000000 - 1418
+ ...
+ Jul 11 15:14:55 52 10cc 00000000000003e9 0000000000000000 - 1306
+ Jul 11 15:14:56 20 18a7 0000000000000000 0000000000000000 -
+ Jul 11 15:14:56 52 18a7 00000000000003e9 0000000000000000 - 1610
+ Jul 11 15:14:57 22 18b5 000000000000031d 0000000000000000 - 1636
+ 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: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
+ 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)
+ <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)
+
+ >>> ZEO.scripts.cache_stats.main('-h cache.trace'.split())
+ loads hits inv(h) writes hitrate
+ Jul 11 12:11-11 0 0 0 0 n/a
+ 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 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 15:15-15 2 1 0 1 50.0%
+ <BLANKLINE>
+ Read 18,837 trace records (640,450 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)
+ <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)
+ <BLANKLINE>
+ Histogram of object load frequency
+ Unique oids: 4,585
+ Total loads: 10,000
+ loads objects %obj %load %cum
+ 1 1,645 35.9% 16.4% 16.4%
+ 2 1,465 32.0% 29.3% 45.8%
+ 3 809 17.6% 24.3% 70.0%
+ 4 430 9.4% 17.2% 87.2%
+ 5 167 3.6% 8.3% 95.6%
+ 6 49 1.1% 2.9% 98.5%
+ 7 12 0.3% 0.8% 99.3%
+ 8 7 0.2% 0.6% 99.9%
+ 9 1 0.0% 0.1% 100.0%
+
+ >>> ZEO.scripts.cache_stats.main('-s cache.trace'.split())
+ ... # doctest: +ELLIPSIS
+ loads hits inv(h) writes hitrate
+ Jul 11 12:11-11 0 0 0 0 n/a
+ 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 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 15:15-15 2 1 0 1 50.0%
+ <BLANKLINE>
+ Read 18,837 trace records (640,450 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)
+ <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)
+ <BLANKLINE>
+ Histograms of object sizes
+ <BLANKLINE>
+ <BLANKLINE>
+ Unique sizes written: 1,781
+ size objs writes
+ 200 6 6
+ 201 4 4
+ 202 5 5
+ 203 1 1
+ 204 1 1
+ 205 6 6
+ 206 8 8
+ ...
+ 1,995 1 2
+ 1,996 2 2
+ 1,997 2 3
+ 1,998 2 2
+ 1,999 2 2
+ 2,000 1 1
+
+ >>> ZEO.scripts.cache_stats.main('-S cache.trace'.split())
+ loads hits inv(h) writes hitrate
+ Jul 11 12:11-11 0 0 0 0 n/a
+ 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 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 15:15-15 2 1 0 1 50.0%
+
+ >>> ZEO.scripts.cache_stats.main('-X cache.trace'.split())
+ loads hits inv(h) writes hitrate
+ Jul 11 12:11-11 0 0 0 0 n/a
+ 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 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 15:15-15 2 1 0 1 50.0%
+ <BLANKLINE>
+ Read 18,837 trace records (640,450 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)
+ <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)
+
+ >>> ZEO.scripts.cache_stats.main('-i 5 cache.trace'.split())
+ loads hits inv(h) writes hitrate
+ Jul 11 12:11-11 0 0 0 0 n/a
+ Jul 11 12:11:41 ==================== Restart ====================
+ Jul 11 12:11-14 180 1 2 197 0.6%
+ Jul 11 12:15-19 272 19 2 281 7.0%
+ Jul 11 12:20-24 273 35 5 265 12.8%
+ Jul 11 12:25-29 273 53 2 247 19.4%
+ 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 15:15-15 2 1 0 1 50.0%
+ <BLANKLINE>
+ Read 18,837 trace records (640,450 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)
+ <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)
+
+ >>> ZEO.scripts.cache_simul.main('-s 2 -i 5 cache.trace'.split())
+ CircularCacheSimulation, cache size 2,097,152 bytes
+ START TIME DUR. LOADS HITS INVALS WRITES HITRATE EVICTS INUSE
+ Jul 11 12:11 3:17 180 1 2 197 0.6% 0 10.7
+ Jul 11 12:15 4:59 272 19 2 281 7.0% 0 26.4
+ Jul 11 12:20 4:59 273 35 5 265 12.8% 0 40.4
+ Jul 11 12:25 4:59 273 53 2 247 19.4% 0 54.8
+ 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:11 3:03:19 10000 3170 327 7830 31.7% 5993 99.9
+
+ >>> cache_run('cache4', 4)
+
+ >>> ZEO.scripts.cache_stats.main('cache4.trace'.split())
+ loads hits inv(h) writes hitrate
+ Jul 11 12:11-11 0 0 0 0 n/a
+ 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 213 22 687 26.0%
+ Jul 11 12:45-59 818 322 23 578 39.4%
+ 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 15:15-15 2 2 0 0 100.0%
+ <BLANKLINE>
+ Read 16,935 trace records (575,782 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)
+ <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)
+
+ >>> ZEO.scripts.cache_simul.main('-s 4 cache.trace'.split())
+ CircularCacheSimulation, cache size 4,194,304 bytes
+ START TIME DUR. LOADS HITS INVALS WRITES HITRATE EVICTS INUSE
+ Jul 11 12:11 3:17 180 1 2 197 0.6% 0 5.4
+ Jul 11 12:15 14:59 818 107 9 793 13.1% 0 27.4
+ Jul 11 12:30 14:59 818 213 22 687 26.0% 0 45.7
+ 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 12:11 3:03:19 10000 5064 504 5936 50.6% 2276 100.0
+
+ >>> cache_run('cache1', 1)
+
+ >>> ZEO.scripts.cache_stats.main('cache1.trace'.split())
+ loads hits inv(h) writes hitrate
+ Jul 11 12:11-11 0 0 0 0 n/a
+ 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 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%
+ <BLANKLINE>
+ Read 20,277 trace records (689,410 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)
+ <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)
+
+ >>> 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:11 3:03:19 10000 1716 173 9284 17.2% 8361 99.9
+
+Cleanup:
+
+ >>> del os.environ["ZEO_CACHE_TRACE"]
+ >>> time.time = timetime
+
+"""
+
def test_suite():
suite = unittest.TestSuite()
suite.addTest(unittest.makeSuite(CacheTests))
Deleted: ZODB/trunk/src/ZODB/scripts/simul.py
===================================================================
--- ZODB/trunk/src/ZODB/scripts/simul.py 2010-07-12 14:37:39 UTC (rev 114632)
+++ ZODB/trunk/src/ZODB/scripts/simul.py 2010-07-12 14:37:40 UTC (rev 114633)
@@ -1,1758 +0,0 @@
-#! /usr/bin/env python
-##############################################################################
-#
-# Copyright (c) 2001-2005 Zope Foundation and Contributors.
-# All Rights Reserved.
-#
-# This software is subject to the provisions of the Zope Public License,
-# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution.
-# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED
-# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
-# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS
-# FOR A PARTICULAR PURPOSE
-#
-##############################################################################
-"""Cache simulation.
-
-Usage: simul.py [-s size] tracefile
-
-Options:
--s size: cache size in MB (default 20 MB)
-"""
-
-import sys
-import time
-import getopt
-import struct
-import math
-import bisect
-from sets import Set
-
-from ZODB.utils import z64
-
-def usage(msg):
- print >> sys.stderr, msg
- print >> sys.stderr, __doc__
-
-def main():
- # Parse options.
- MB = 1024**2
- cachelimit = 20*MB
- simclass = CircularCacheSimulation
- try:
- opts, args = getopt.getopt(sys.argv[1:], "bflyz2cOaTUs:")
- except getopt.error, msg:
- usage(msg)
- return 2
- for o, a in opts:
- if o == '-b':
- simclass = BuddyCacheSimulation
- elif o == '-f':
- simclass = SimpleCacheSimulation
- elif o == '-l':
- simclass = LRUCacheSimulation
- elif o == '-y':
- simclass = AltZEOCacheSimulation
- elif o == '-z':
- simclass = ZEOCacheSimulation
- elif o == '-s':
- cachelimit = int(float(a)*MB)
- elif o == '-2':
- simclass = TwoQSimluation
- elif o == '-c':
- simclass = CircularCacheSimulation
- elif o == '-O':
- simclass = OracleSimulation
- elif o == '-a':
- simclass = ARCCacheSimulation
- elif o == '-T':
- simclass = ThorSimulation
- elif o == '-U':
- simclass = UnboundedSimulation
- else:
- assert False, (o, a)
-
- if len(args) != 1:
- usage("exactly one file argument required")
- return 2
- filename = args[0]
-
- # Open file.
- if filename.endswith(".gz"):
- # Open gzipped file.
- try:
- import gzip
- except ImportError:
- print >> sys.stderr, "can't read gzipped files (no module gzip)"
- return 1
- try:
- f = gzip.open(filename, "rb")
- except IOError, msg:
- print >> sys.stderr, "can't open %s: %s" % (filename, msg)
- return 1
- elif filename == "-":
- # Read from stdin.
- f = sys.stdin
- else:
- # Open regular file.
- try:
- f = open(filename, "rb")
- except IOError, msg:
- print >> sys.stderr, "can't open %s: %s" % (filename, msg)
- return 1
-
- # Create simulation object.
- if simclass is OracleSimulation:
- sim = simclass(cachelimit, filename)
- else:
- sim = simclass(cachelimit)
-
- # Print output header.
- sim.printheader()
-
- # Read trace file, simulating cache behavior.
- f_read = f.read
- unpack = struct.unpack
- FMT = ">iiH8s8s"
- FMT_SIZE = struct.calcsize(FMT)
- assert FMT_SIZE == 26
- while 1:
- # Read a record and decode it.
- r = f_read(FMT_SIZE)
- if len(r) < FMT_SIZE:
- break
- ts, code, oidlen, start_tid, end_tid = unpack(FMT, r)
- if ts == 0:
- # Must be a misaligned record caused by a crash; skip 8 bytes
- # and try again. Why 8? Lost in the mist of history.
- f.seek(f.tell() - FMT_SIZE + 8)
- continue
- oid = f_read(oidlen)
- if len(oid) < oidlen:
- break
- # Decode the code.
- dlen, version, code = (code & 0x7fffff00,
- code & 0x80,
- code & 0x7e)
- # And pass it to the simulation.
- sim.event(ts, dlen, version, code, oid, start_tid, end_tid)
-
- f.close()
- # Finish simulation.
- sim.finish()
-
- # Exit code from main().
- return 0
-
-class Simulation(object):
- """Base class for simulations.
-
- The driver program calls: event(), printheader(), finish().
-
- The standard event() method calls these additional methods:
- write(), load(), inval(), report(), restart(); the standard
- finish() method also calls report().
- """
-
- def __init__(self, cachelimit):
- self.cachelimit = cachelimit
- # Initialize global statistics.
- self.epoch = None
- self.total_loads = 0
- self.total_hits = 0 # subclass must increment
- self.total_invals = 0 # subclass must increment
- self.total_writes = 0
- if not hasattr(self, "extras"):
- self.extras = (self.extraname,)
- self.format = self.format + " %7s" * len(self.extras)
- # Reset per-run statistics and set up simulation data.
- self.restart()
-
- def restart(self):
- # Reset per-run statistics.
- self.loads = 0
- self.hits = 0 # subclass must increment
- self.invals = 0 # subclass must increment
- self.writes = 0
- self.ts0 = None
-
- def event(self, ts, dlen, _version, code, oid,
- start_tid, end_tid):
- # Record first and last timestamp seen.
- if self.ts0 is None:
- self.ts0 = ts
- if self.epoch is None:
- self.epoch = ts
- self.ts1 = ts
-
- # Simulate cache behavior. Caution: the codes in the trace file
- # record whether the actual cache missed or hit on each load, but
- # that bears no necessary relationship to whether the simulated cache
- # will hit or miss. Relatedly, if the actual cache needed to store
- # an object, the simulated cache may not need to (it may already
- # have the data).
- action = code & 0x70
- if action == 0x20:
- # Load.
- self.loads += 1
- self.total_loads += 1
- # Asserting that dlen is 0 iff it's a load miss.
- # assert (dlen == 0) == (code in (0x20, 0x24))
- self.load(oid, dlen, start_tid)
- elif action == 0x50:
- # Store.
- assert dlen
- self.write(oid, dlen, start_tid, end_tid)
- elif action == 0x10:
- # Invalidate.
- self.inval(oid, start_tid)
- elif action == 0x00:
- # Restart.
- self.report()
- self.restart()
- else:
- raise ValueError("unknown trace code 0x%x" % code)
-
- def write(self, oid, size, start_tid, end_tid):
- pass
-
- def load(self, oid, size, start_tid):
- # Must increment .hits and .total_hits as appropriate.
- pass
-
- def inval(self, oid, start_tid):
- # Must increment .invals and .total_invals as appropriate.
- pass
-
- format = "%12s %9s %8s %8s %6s %6s %7s"
-
- # Subclass should override extraname to name known instance variables;
- # if extraname is 'foo', both self.foo and self.total_foo must exist:
- extraname = "*** please override ***"
-
- def printheader(self):
- print "%s, cache size %s bytes" % (self.__class__.__name__,
- addcommas(self.cachelimit))
- self.extraheader()
- extranames = tuple([s.upper() for s in self.extras])
- args = ("START TIME", "DURATION", "LOADS", "HITS",
- "INVALS", "WRITES", "HITRATE") + extranames
- print self.format % args
-
- def extraheader(self):
- pass
-
- nreports = 0
-
- def report(self, extratext=''):
- if self.loads:
- self.nreports += 1
- args = (time.ctime(self.ts0)[4:-8],
- duration(self.ts1 - self.ts0),
- self.loads, self.hits, self.invals, self.writes,
- hitrate(self.loads, self.hits))
- args += tuple([getattr(self, name) for name in self.extras])
- print self.format % args, extratext
-
- def finish(self):
- # Make sure that the last line of output ends with "OVERALL". This
- # makes it much easier for another program parsing the output to
- # find summary statistics.
- if self.nreports < 2:
- self.report('OVERALL')
- else:
- self.report()
- args = (
- time.ctime(self.epoch)[4:-8],
- duration(self.ts1 - self.epoch),
- self.total_loads,
- self.total_hits,
- self.total_invals,
- self.total_writes,
- hitrate(self.total_loads, self.total_hits))
- args += tuple([getattr(self, "total_" + name)
- for name in self.extras])
- print (self.format + " OVERALL") % args
-
-
-# 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',
-
- # 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',
- )
-
- def __init__(self, key, end_tid, offset):
- self.key = key
- self.end_tid = end_tid
- self.offset = offset
-
-from ZEO.cache import ZEC3_HEADER_SIZE
-
-class CircularCacheSimulation(Simulation):
- """Simulate the ZEO 3.0 cache."""
-
- # The cache is managed as a single file with a pointer that
- # goes around the file, circularly, forever. New objects
- # are written at the current pointer, evicting whatever was
- # there previously.
-
- extras = "evicts", "inuse"
-
- def __init__(self, cachelimit):
- from ZEO import cache
-
- Simulation.__init__(self, cachelimit)
- self.total_evicts = 0 # number of cache evictions
-
- # Current offset in file.
- self.offset = ZEC3_HEADER_SIZE
-
- # Map offset in file to (size, CircularCacheEntry) pair, or to
- # (size, None) if the offset starts a free block.
- self.filemap = {ZEC3_HEADER_SIZE: (self.cachelimit - ZEC3_HEADER_SIZE,
- None)}
- # Map key to CircularCacheEntry. A key is an (oid, tid) pair.
- self.key2entry = {}
-
- # Map oid to tid of current revision.
- self.current = {}
-
- # Map oid to list of (start_tid, end_tid) pairs in sorted order.
- # Used to find matching key for load of non-current data.
- self.noncurrent = {}
-
- # The number of overhead bytes needed to store an object pickle
- # on disk (all bytes beyond those needed for the object pickle).
- self.overhead = (cache.Object.TOTAL_FIXED_SIZE +
- cache.OBJECT_HEADER_SIZE)
-
- def restart(self):
- Simulation.restart(self)
- self.evicts = 0
-
- def load(self, oid, size, tid):
- if tid == z64:
- # Trying to load current revision.
- if oid in self.current: # else it's a cache miss
- self.hits += 1
- self.total_hits += 1
- return
-
- # May or may not be trying to load current revision.
- cur_tid = self.current.get(oid)
- if cur_tid == tid:
- self.hits += 1
- self.total_hits += 1
- return
-
- # It's a load for non-current data. Do we know about this oid?
- L = self.noncurrent.get(oid)
- if L is None:
- return # cache miss
- i = bisect.bisect_left(L, (tid, None))
- if i == 0:
- # This tid is smaller than any we know about -- miss.
- return
- lo, hi = L[i-1]
- assert lo < tid
- if tid > hi:
- # No data in the right tid range -- miss.
- return
- # Cache hit.
- self.hits += 1
- self.total_hits += 1
-
- # (oid, tid) is in the cache. Remove it: take it out of key2entry,
- # and in `filemap` mark the space it occupied as being free. The
- # caller is responsible for removing it from `current` or `noncurrent`.
- def _remove(self, oid, tid):
- key = oid, tid
- e = self.key2entry.pop(key)
- pos = e.offset
- size, _e = self.filemap[pos]
- assert e is _e
- self.filemap[pos] = size, None
-
- def _remove_noncurrent_revisions(self, oid):
- noncurrent_list = self.noncurrent.get(oid)
- if noncurrent_list:
- self.invals += len(noncurrent_list)
- self.total_invals += len(noncurrent_list)
- for start_tid, end_tid in noncurrent_list:
- self._remove(oid, start_tid)
- del self.noncurrent[oid]
-
- def inval(self, oid, tid):
- if tid == z64:
- # This is part of startup cache verification: forget everything
- # about this oid.
- self._remove_noncurrent_revisions(oid)
-
- cur_tid = self.current.get(oid)
- if cur_tid is None:
- # We don't have current data, so nothing more to do.
- return
-
- # We had current data for oid, but no longer.
- self.invals += 1
- self.total_invals += 1
- del self.current[oid]
- if tid == z64:
- # Startup cache verification: forget this oid entirely.
- self._remove(oid, cur_tid)
- return
-
- # Our current data becomes non-current data.
- # Add the validity range to the list of non-current data for oid.
- assert cur_tid < tid
- L = self.noncurrent.setdefault(oid, [])
- bisect.insort_left(L, (cur_tid, tid))
- # Update the end of oid's validity range in its CircularCacheEntry.
- e = self.key2entry[oid, cur_tid]
- assert e.end_tid == z64
- e.end_tid = tid
-
- def write(self, oid, size, start_tid, end_tid):
- if end_tid == z64:
- # Storing current revision.
- if oid in self.current: # we already have it in cache
- return
- self.current[oid] = start_tid
- self.writes += 1
- self.total_writes += 1
- self.add(oid, size, start_tid)
- return
- # Storing non-current revision.
- L = self.noncurrent.setdefault(oid, [])
- p = start_tid, end_tid
- if p in L:
- return # we already have it in cache
- bisect.insort_left(L, p)
- self.writes += 1
- self.total_writes += 1
- self.add(oid, size, start_tid, end_tid)
-
- # Add `oid` to the cache, evicting objects as needed to make room.
- # This updates `filemap` and `key2entry`; it's the caller's
- # responsibilty to update `current` or `noncurrent` appropriately.
- def add(self, oid, size, start_tid, end_tid=z64):
- key = oid, start_tid
- assert key not in self.key2entry
- size += self.overhead
- avail = self.makeroom(size)
- e = CircularCacheEntry(key, end_tid, self.offset)
- self.filemap[self.offset] = size, e
- self.key2entry[key] = e
- self.offset += size
- # All the space made available must be accounted for in filemap.
- excess = avail - size
- if excess:
- self.filemap[self.offset] = excess, None
-
- # Evict enough objects to make at least `need` contiguous bytes, starting
- # at `self.offset`, available. Evicted objects are removed from
- # `filemap`, `key2entry`, `current` and `noncurrent`. The caller is
- # responsible for adding new entries to `filemap` to account for all
- # the freed bytes, and for advancing `self.offset`. The number of bytes
- # freed is the return value, and will be >= need.
- def makeroom(self, need):
- if self.offset + need > self.cachelimit:
- self.offset = ZEC3_HEADER_SIZE
- pos = self.offset
- while need > 0:
- assert pos < self.cachelimit
- size, e = self.filemap.pop(pos)
- if e: # there is an object here (else it's already free space)
- self.evicts += 1
- self.total_evicts += 1
- assert pos == e.offset
- _e = self.key2entry.pop(e.key)
- assert e is _e
- oid, start_tid = e.key
- if e.end_tid == z64:
- del self.current[oid]
- else:
- L = self.noncurrent[oid]
- L.remove((start_tid, e.end_tid))
- need -= size
- pos += size
- return pos - self.offset # total number of bytes freed
-
- def report(self):
- self.check()
- free = used = total = 0
- for size, e in self.filemap.itervalues():
- total += size
- if e:
- used += size
- else:
- free += size
-
- self.inuse = round(100.0 * used / total, 1)
- self.total_inuse = self.inuse
- Simulation.report(self)
-
- def check(self):
- oidcount = 0
- pos = ZEC3_HEADER_SIZE
- while pos < self.cachelimit:
- size, e = self.filemap[pos]
- if e:
- oidcount += 1
- assert self.key2entry[e.key].offset == pos
- pos += size
- assert oidcount == len(self.key2entry)
- assert pos == self.cachelimit
-
- def dump(self):
- print len(self.filemap)
- L = list(self.filemap)
- L.sort()
- for k in L:
- v = self.filemap[k]
- print k, v[0], repr(v[1])
-
-#############################################################################
-# CAUTION: It's most likely that none of the simulators below this
-# point work anymore. A great many changes were needed to teach
-# CircularCacheSimulation (above) about MVCC, including method signature
-# changes and changes in cache file format, and none of the other simulator
-# classes were changed.
-#############################################################################
-
-class ZEOCacheSimulation(Simulation):
- """Simulate the ZEO 1.0 and 2.0 cache behavior.
-
- This assumes the cache is not persistent (we don't know how to
- simulate cache validation.)
- """
-
- extraname = "flips"
-
- def __init__(self, cachelimit):
- # Initialize base class
- Simulation.__init__(self, cachelimit)
- # Initialize additional global statistics
- self.total_flips = 0
-
- def restart(self):
- # Reset base class
- Simulation.restart(self)
- # Reset additional per-run statistics
- self.flips = 0
- # Set up simulation
- self.filesize = [4, 4] # account for magic number
- self.fileoids = [{}, {}]
- self.current = 0 # index into filesize, fileoids
-
- def load(self, oid, size):
- if (self.fileoids[self.current].get(oid) or
- self.fileoids[1 - self.current].get(oid)):
- self.hits += 1
- self.total_hits += 1
- else:
- self.write(oid, size)
-
- def write(self, oid, size):
- # Fudge because size is rounded up to multiples of 256. (31
- # is header overhead per cache record; 127 is to compensate
- # for rounding up to multiples of 256.)
- size = size + 31 - 127
- if self.filesize[self.current] + size > self.cachelimit / 2:
- # Cache flip
- self.flips += 1
- self.total_flips += 1
- self.current = 1 - self.current
- self.filesize[self.current] = 4
- self.fileoids[self.current] = {}
- self.filesize[self.current] += size
- self.fileoids[self.current][oid] = 1
-
- def inval(self, oid):
- if self.fileoids[self.current].get(oid):
- self.invals += 1
- self.total_invals += 1
- del self.fileoids[self.current][oid]
- elif self.fileoids[1 - self.current].get(oid):
- self.invals += 1
- self.total_invals += 1
- del self.fileoids[1 - self.current][oid]
-
-class AltZEOCacheSimulation(ZEOCacheSimulation):
- """A variation of the ZEO cache that copies to the current file.
-
- When a hit is found in the non-current cache file, it is copied to
- the current cache file. Exception: when the copy would cause a
- cache flip, we don't copy (this is part laziness, part concern
- over causing extraneous flips).
- """
-
- def load(self, oid, size):
- if self.fileoids[self.current].get(oid):
- self.hits += 1
- self.total_hits += 1
- elif self.fileoids[1 - self.current].get(oid):
- self.hits += 1
- self.total_hits += 1
- # Simulate a write, unless it would cause a flip
- size = size + 31 - 127
- if self.filesize[self.current] + size <= self.cachelimit / 2:
- self.filesize[self.current] += size
- self.fileoids[self.current][oid] = 1
- del self.fileoids[1 - self.current][oid]
- else:
- self.write(oid, size)
-
-class LRUCacheSimulation(Simulation):
-
- extraname = "evicts"
-
- def __init__(self, cachelimit):
- # Initialize base class
- Simulation.__init__(self, cachelimit)
- # Initialize additional global statistics
- self.total_evicts = 0
-
- def restart(self):
- # Reset base class
- Simulation.restart(self)
- # Reset additional per-run statistics
- self.evicts = 0
- # Set up simulation
- self.cache = {}
- self.size = 0
- self.head = Node(None, None)
- self.head.linkbefore(self.head)
-
- def load(self, oid, size):
- node = self.cache.get(oid)
- if node is not None:
- self.hits += 1
- self.total_hits += 1
- node.linkbefore(self.head)
- else:
- self.write(oid, size)
-
- def write(self, oid, size):
- node = self.cache.get(oid)
- if node is not None:
- node.unlink()
- assert self.head.next is not None
- self.size -= node.size
- node = Node(oid, size)
- self.cache[oid] = node
- node.linkbefore(self.head)
- self.size += size
- # Evict LRU nodes
- while self.size > self.cachelimit:
- self.evicts += 1
- self.total_evicts += 1
- node = self.head.next
- assert node is not self.head
- node.unlink()
- assert self.head.next is not None
- del self.cache[node.oid]
- self.size -= node.size
-
- def inval(self, oid):
- node = self.cache.get(oid)
- if node is not None:
- assert node.oid == oid
- self.invals += 1
- self.total_invals += 1
- node.unlink()
- assert self.head.next is not None
- del self.cache[oid]
- self.size -= node.size
- assert self.size >= 0
-
-class Node(object):
- """Node in a doubly-linked list, storing oid and size as payload.
-
- A node can be linked or unlinked; in the latter case, next and
- prev are None. Initially a node is unlinked.
- """
-
- __slots__ = ['prev', 'next', 'oid', 'size']
-
- def __init__(self, oid, size):
- self.oid = oid
- self.size = size
- self.prev = self.next = None
-
- def unlink(self):
- prev = self.prev
- next = self.next
- if prev is not None:
- assert next is not None
- assert prev.next is self
- assert next.prev is self
- prev.next = next
- next.prev = prev
- self.prev = self.next = None
- else:
- assert next is None
-
- def linkbefore(self, next):
- self.unlink()
- prev = next.prev
- if prev is None:
- assert next.next is None
- prev = next
- self.prev = prev
- self.next = next
- prev.next = next.prev = self
-
-am = object()
-a1in = object()
-a1out = object()
-
-class Node2Q(Node):
-
- __slots__ = ["kind", "hits"]
-
- def __init__(self, oid, size, kind=None):
- Node.__init__(self, oid, size)
- self.kind = kind
- self.hits = 0
-
- def linkbefore(self, next):
- if next.kind != self.kind:
- self.kind = next.kind
- Node.linkbefore(self, next)
-
-class TwoQSimluation(Simulation):
- # The original 2Q algorithm is page based and the authors offer
- # tuning guidlines based on a page-based cache. Our cache is
- # object based, so, for example, it's hard to compute the number
- # of oids to store in a1out based on the size of a1in.
-
- extras = "evicts", "hothit", "am_add"
-
- NodeClass = Node2Q
-
- def __init__(self, cachelimit, outlen=10000, threshold=0):
- Simulation.__init__(self, cachelimit)
-
- # The promotion threshold: If a hit occurs in a1out, it is
- # promoted to am if the number of hits on the object while it
- # was in a1in is at least threshold. The standard 2Q scheme
- # uses a threshold of 0.
- self.threshold = threshold
- self.am_limit = 3 * self.cachelimit / 4
- self.a1in_limit = self.cachelimit / 4
-
- self.cache = {}
- self.am_size = 0
- self.a1in_size = 0
- self.a1out_size = 0
-
- self.total_evicts = 0
- self.total_hothit = 0
- self.total_am_add = 0
- self.a1out_limit = outlen
-
- # An LRU queue of hot objects
- self.am = self.NodeClass(None, None, am)
- self.am.linkbefore(self.am)
- # A FIFO queue of recently referenced objects. It's purpose
- # is to absorb references to objects that are accessed a few
- # times in short order, then forgotten about.
- self.a1in = self.NodeClass(None, None, a1in)
- self.a1in.linkbefore(self.a1in)
- # A FIFO queue of recently reference oids.
- # This queue only stores the oids, not any data. If we get a
- # hit in this queue, promote the object to am.
- self.a1out = self.NodeClass(None, None, a1out)
- self.a1out.linkbefore(self.a1out)
-
- def makespace(self, size):
- for space in 0, size:
- if self.enoughspace(size):
- return
- self.evict_a1in(space)
- if self.enoughspace(size):
- return
- self.evict_am(space)
-
- def enoughspace(self, size):
- totalsize = self.a1in_size + self.am_size
- return totalsize + size < self.cachelimit
-
- def evict_a1in(self, extra):
- while self.a1in_size + extra > self.a1in_limit:
- if self.a1in.next is self.a1in:
- return
- assert self.a1in.next is not None
- node = self.a1in.next
- self.evicts += 1
- self.total_evicts += 1
- node.linkbefore(self.a1out)
- self.a1out_size += 1
- self.a1in_size -= node.size
- if self.a1out_size > self.a1out_limit:
- assert self.a1out.next is not None
- node = self.a1out.next
- node.unlink()
- del self.cache[node.oid]
- self.a1out_size -= 1
-
- def evict_am(self, extra):
- while self.am_size + extra > self.am_limit:
- if self.am.next is self.am:
- return
- assert self.am.next is not None
- node = self.am.next
- self.evicts += 1
- self.total_evicts += 1
- # This node hasn't been accessed in a while, so just
- # forget about it.
- node.unlink()
- del self.cache[node.oid]
- self.am_size -= node.size
-
- def write(self, oid, size):
- # A write always follows a read (ZODB doesn't allow blind writes).
- # So this write must have followed a recent read of the object.
- # Don't change it's position, but do update the size.
-
- # XXX For now, don't evict pages if the new version of the object
- # is big enough to require eviction.
- node = self.cache.get(oid)
- if node is None or node.kind is a1out:
- return
- if node.kind is am:
- self.am_size = self.am_size - node.size + size
- node.size = size
- else:
- self.a1in_size = self.a1in_size - node.size + size
- node.size = size
-
- def load(self, oid, size):
- node = self.cache.get(oid)
- if node is not None:
- if node.kind is am:
- self.hits += 1
- self.total_hits += 1
- self.hothit += 1
- self.total_hothit += 1
- node.hits += 1
- node.linkbefore(self.am)
- elif node.kind is a1in:
- self.hits += 1
- self.total_hits += 1
- node.hits += 1
- elif node.kind is a1out:
- self.a1out_size -= 1
- if node.hits >= self.threshold:
- self.makespace(node.size)
- self.am_size += node.size
- node.linkbefore(self.am)
- self.cache[oid] = node
- self.am_add += 1
- self.total_am_add += 1
- else:
- node.unlink()
- self.insert(oid, size)
- else:
- self.insert(oid, size)
-
- def insert(self, oid, size):
- # New objects enter the cache via a1in. If they
- # are frequently used over a long enough time, they
- # will be promoted to am -- but only via a1out.
- self.makespace(size)
- node = self.NodeClass(oid, size, a1in)
- node.linkbefore(self.a1in)
- self.cache[oid] = node
- self.a1in_size += node.size
-
- def inval(self, oid):
- # The original 2Q algorithm didn't have to deal with
- # invalidations. My own solution: Move it to the head of
- # a1out.
- node = self.cache.get(oid)
- if node is None:
- return
- self.invals += 1
- self.total_invals += 1
- # XXX Should an invalidation to a1out count?
- if node.kind is a1out:
- return
- node.linkbefore(self.a1out)
- if node.kind is am:
- self.am_size -= node.size
- else:
- self.a1in_size -= node.size
-
- def restart(self):
- Simulation.restart(self)
-
- self.evicts = 0
- self.hothit = 0
- self.am_add = 0
-
-lruT = object()
-lruB = object()
-fifoT = object()
-fifoB = object()
-
-class ARCCacheSimulation(Simulation):
-
- # Based on the paper ARC: A Self-Tuning, Low Overhead Replacement
- # Cache by Nimrod Megiddo and Dharmendra S. Modha, USENIX FAST
- # 2003. The paper describes a block-based cache. A lot of the
- # details need to be fiddled to work with an object-based cache.
- # For size issues, the key insight ended up being conditions
- # A.1-A.5 rather than the details of the algorithm in Fig. 4.
-
- extras = "lruThits", "evicts", "p"
-
- def __init__(self, cachelimit):
- Simulation.__init__(self, cachelimit)
- # There are two pairs of linked lists. Each pair has a top and
- # bottom half. The bottom half contains metadata, but not actual
- # objects.
-
- # LRU list of frequently used objects
- self.lruT = Node2Q(None, None, lruT)
- self.lruT.linkbefore(self.lruT)
- self.lruT_len = 0
- self.lruT_size = 0
-
- self.lruB = Node2Q(None, None, lruB)
- self.lruB.linkbefore(self.lruB)
- self.lruB_len = 0
- self.lruB_size = 0
-
- # FIFO list of objects seen once
- self.fifoT = Node2Q(None, None, fifoT)
- self.fifoT.linkbefore(self.fifoT)
- self.fifoT_len = 0
- self.fifoT_size = 0
-
- self.fifoB = Node2Q(None, None, fifoB)
- self.fifoB.linkbefore(self.fifoB)
- self.fifoB_len = 0
- self.fifoB_size = 0
-
- # maps oid to node
- self.cache = {}
-
- # The paper says that p should be adjust be 1 as the minimum:
- # "The compound effect of such small increments and decrements
- # to p s quite profound as we will demonstrated in the next
- # section." Not really, as far as I can tell. In my traces
- # with a very small cache, it was taking far too long to adjust
- # towards favoring some FIFO component. I would guess that the
- # chief difference is that our caches are much bigger than the
- # ones they experimented with. Their biggest cache had 512K
- # entries, while our smallest cache will have 40 times that many
- # entries.
-
- self.p = 0
- # XXX multiply computed adjustments to p by walk_factor
- self.walk_factor = 500
-
- # statistics
- self.total_hits = 0
- self.total_lruThits = 0
- self.total_fifoThits = 0
- self.total_evicts = 0
-
- def restart(self):
- Simulation.restart(self)
- self.hits = 0
- self.lruThits = 0
- self.fifoThits = 0
- self.evicts = 0
-
- def write(self, oid, size):
- pass
-
- def replace(self, lruB=False):
- self.evicts += 1
- self.total_evicts += 1
- if self.fifoT_size > self.p or (lruB and self.fifoT_size == self.p):
- node = self.fifoT.next
- if node is self.fifoT:
- return 0
- assert node is not self.fifoT, self.stats()
- node.linkbefore(self.fifoB)
- self.fifoT_len -= 1
- self.fifoT_size -= node.size
- self.fifoB_len += 1
- self.fifoB_size += node.size
- else:
- node = self.lruT.next
- if node is self.lruT:
- return 0
- assert node is not self.lruT, self.stats()
- node.linkbefore(self.lruB)
- self.lruT_len -= 1
- self.lruT_size -= node.size
- self.lruB_len += 1
- self.lruB_size += node.size
- return node.size
-
- def stats(self):
- self.totalsize = self.lruT_size + self.fifoT_size
- self.allsize = self.totalsize + self.lruB_size + self.fifoB_size
- print "cachelimit = %s totalsize=%s allsize=%s" % (
- addcommas(self.cachelimit),
- addcommas(self.totalsize),
- addcommas(self.allsize))
-
- fmt = (
- "p=%(p)d\n"
- "lruT = %(lruT_len)5d / %(lruT_size)8d / %(lruThits)d\n"
- "fifoT = %(fifoT_len)5d / %(fifoT_size)8d / %(fifoThits)d\n"
- "lruB = %(lruB_len)5d / %(lruB_size)8d\n"
- "fifoB = %(fifoB_len)5d / %(fifoB_size)8d\n"
- "loads=%(loads)d hits=%(hits)d evicts=%(evicts)d\n"
- )
- print fmt % self.__dict__
-
- def report(self):
- self.total_p = self.p
- Simulation.report(self)
-## self.stats()
-
- def load(self, oid, size):
-## maybe(self.stats, p=0.002)
- node = self.cache.get(oid)
- if node is None:
- # cache miss: We're going to insert a new object in fifoT.
- # If fifo is full, we'll need to evict something to make
- # room for it.
-
- prev = need = size
- while need > 0:
- if size + self.fifoT_size + self.fifoB_size >= self.cachelimit:
- if need + self.fifoT_size >= self.cachelimit:
- node = self.fifoB.next
- assert node is not self.fifoB, self.stats()
- node.unlink()
- del self.cache[node.oid]
- self.fifoB_size -= node.size
- self.fifoB_len -= 1
- self.evicts += 1
- self.total_evicts += 1
- else:
- node = self.fifoB.next
- assert node is not self.fifoB, self.stats()
- node.unlink()
- del self.cache[node.oid]
- self.fifoB_size -= node.size
- self.fifoB_len -= 1
- if self.fifoT_size + self.lruT_size > self.cachelimit:
- need -= self.replace()
- else:
- incache_size = self.fifoT_size + self.lruT_size + need
- total_size = (incache_size + self.fifoB_size
- + self.lruB_size)
- if total_size >= self.cachelimit * 2:
- node = self.lruB.next
- if node is self.lruB:
- break
- assert node is not self.lruB
- node.unlink()
- del self.cache[node.oid]
- self.lruB_size -= node.size
- self.lruB_len -= 1
- elif incache_size > self.cachelimit:
- need -= self.replace()
- else:
- break
- if need == prev:
- # XXX hack, apparently we can't get rid of anything else
- break
- prev = need
-
- node = Node2Q(oid, size)
- node.linkbefore(self.fifoT)
- self.fifoT_len += 1
- self.fifoT_size += size
- self.cache[oid] = node
- else:
- # a cache hit, but possibly in a bottom list that doesn't
- # actually hold the object
- if node.kind is lruT:
- node.linkbefore(self.lruT)
-
- self.hits += 1
- self.total_hits += 1
- self.lruThits += 1
- self.total_lruThits += 1
-
- elif node.kind is fifoT:
- node.linkbefore(self.lruT)
- self.fifoT_len -= 1
- self.lruT_len += 1
- self.fifoT_size -= node.size
- self.lruT_size += node.size
-
- self.hits += 1
- self.total_hits += 1
- self.fifoThits += 1
- self.total_fifoThits += 1
-
- elif node.kind is fifoB:
- node.linkbefore(self.lruT)
- self.fifoB_len -= 1
- self.lruT_len += 1
- self.fifoB_size -= node.size
- self.lruT_size += node.size
-
- # XXX need a better min than 1?
-## print "adapt+", max(1, self.lruB_size // self.fifoB_size)
- delta = max(1, self.lruB_size / max(1, self.fifoB_size))
- self.p += delta * self.walk_factor
- if self.p > self.cachelimit:
- self.p = self.cachelimit
-
- need = node.size
- if self.lruT_size + self.fifoT_size + need > self.cachelimit:
- while need > 0:
- r = self.replace()
- if not r:
- break
- need -= r
-
- elif node.kind is lruB:
- node.linkbefore(self.lruT)
- self.lruB_len -= 1
- self.lruT_len += 1
- self.lruB_size -= node.size
- self.lruT_size += node.size
-
- # XXX need a better min than 1?
-## print "adapt-", max(1, self.fifoB_size // self.lruB_size)
- delta = max(1, self.fifoB_size / max(1, self.lruB_size))
- self.p -= delta * self.walk_factor
- if self.p < 0:
- self.p = 0
-
- need = node.size
- if self.lruT_size + self.fifoT_size + need > self.cachelimit:
- while need > 0:
- r = self.replace(lruB=True)
- if not r:
- break
- need -= r
-
- def inval(self, oid):
- pass
-
- def extraheader(self):
- pass
-
-class OracleSimulation(LRUCacheSimulation):
- # Not sure how to implement this yet. This is a cache where I
- # cheat to see how good we could actually do. The cache
- # replacement problem for multi-size caches is NP-hard, so we're
- # not going to have an optimal solution.
-
- # At the moment, the oracle is mostly blind. It knows which
- # objects will be referenced more than once, so that it can
- # ignore objects referenced only once. In most traces, these
- # objects account for about 20% of references.
-
- def __init__(self, cachelimit, filename):
- LRUCacheSimulation.__init__(self, cachelimit)
- self.count = {}
- self.scan(filename)
-
- def load(self, oid, size):
- node = self.cache.get(oid)
- if node is not None:
- self.hits += 1
- self.total_hits += 1
- node.linkbefore(self.head)
- else:
- if oid in self.count:
- self.write(oid, size)
-
- def scan(self, filename):
- # scan the file in advance to figure out which objects will
- # be referenced more than once.
- f = open(filename, "rb")
- struct_unpack = struct.unpack
- f_read = f.read
- offset = 0
- while 1:
- # Read a record and decode it
- r = f_read(8)
- if len(r) < 8:
- break
- offset += 8
- ts, code = struct_unpack(">ii", r)
- if ts == 0:
- # Must be a misaligned record caused by a crash
- ##print "Skipping 8 bytes at offset", offset-8
- continue
- r = f_read(16)
- if len(r) < 16:
- break
- offset += 16
- oid, serial = struct_unpack(">8s8s", r)
- if code & 0x70 == 0x20:
- # only look at loads
- self.count[oid] = self.count.get(oid, 0) + 1
-
- all = len(self.count)
-
- # Now remove everything with count == 1
- once = [oid for oid, count in self.count.iteritems()
- if count == 1]
- for oid in once:
- del self.count[oid]
-
- print "Scanned file, %d unique oids, %d repeats" % (
- all, len(self.count))
-
-class BuddyCacheSimulation(LRUCacheSimulation):
-
- def __init__(self, cachelimit):
- LRUCacheSimulation.__init__(self, roundup(cachelimit))
-
- def restart(self):
- LRUCacheSimulation.restart(self)
- self.allocator = self.allocatorFactory(self.cachelimit)
-
- def allocatorFactory(self, size):
- return BuddyAllocator(size)
-
- # LRUCacheSimulation.load() is just fine
-
- def write(self, oid, size):
- node = self.cache.get(oid)
- if node is not None:
- node.unlink()
- assert self.head.next is not None
- self.size -= node.size
- self.allocator.free(node)
- while 1:
- node = self.allocator.alloc(size)
- if node is not None:
- break
- # Failure to allocate. Evict something and try again.
- node = self.head.next
- assert node is not self.head
- self.evicts += 1
- self.total_evicts += 1
- node.unlink()
- assert self.head.next is not None
- del self.cache[node.oid]
- self.size -= node.size
- self.allocator.free(node)
- node.oid = oid
- self.cache[oid] = node
- node.linkbefore(self.head)
- self.size += node.size
-
- def inval(self, oid):
- node = self.cache.get(oid)
- if node is not None:
- assert node.oid == oid
- self.invals += 1
- self.total_invals += 1
- node.unlink()
- assert self.head.next is not None
- del self.cache[oid]
- self.size -= node.size
- assert self.size >= 0
- self.allocator.free(node)
-
-class SimpleCacheSimulation(BuddyCacheSimulation):
-
- def allocatorFactory(self, size):
- return SimpleAllocator(size)
-
- def finish(self):
- BuddyCacheSimulation.finish(self)
- self.allocator.report()
-
-MINSIZE = 256
-
-class BuddyAllocator:
-
- def __init__(self, cachelimit):
- cachelimit = roundup(cachelimit)
- self.cachelimit = cachelimit
- self.avail = {} # Map rounded-up sizes to free list node heads
- self.nodes = {} # Map address to node
- k = MINSIZE
- while k <= cachelimit:
- self.avail[k] = n = Node(None, None) # Not BlockNode; has no addr
- n.linkbefore(n)
- k += k
- node = BlockNode(None, cachelimit, 0)
- self.nodes[0] = node
- node.linkbefore(self.avail[cachelimit])
-
- def alloc(self, size):
- size = roundup(size)
- k = size
- while k <= self.cachelimit:
- head = self.avail[k]
- node = head.next
- if node is not head:
- break
- k += k
- else:
- return None # Store is full, or block is too large
- node.unlink()
- size2 = node.size
- while size2 > size:
- size2 = size2 / 2
- assert size2 >= size
- node.size = size2
- buddy = BlockNode(None, size2, node.addr + size2)
- self.nodes[buddy.addr] = buddy
- buddy.linkbefore(self.avail[size2])
- node.oid = 1 # Flag as in-use
- return node
-
- def free(self, node):
- assert node is self.nodes[node.addr]
- assert node.prev is node.next is None
- node.oid = None # Flag as free
- while node.size < self.cachelimit:
- buddy_addr = node.addr ^ node.size
- buddy = self.nodes[buddy_addr]
- assert buddy.addr == buddy_addr
- if buddy.oid is not None or buddy.size != node.size:
- break
- # Merge node with buddy
- buddy.unlink()
- if buddy.addr < node.addr: # buddy prevails
- del self.nodes[node.addr]
- node = buddy
- else: # node prevails
- del self.nodes[buddy.addr]
- node.size *= 2
- assert node is self.nodes[node.addr]
- node.linkbefore(self.avail[node.size])
-
- def dump(self, msg=""):
- if msg:
- print msg,
- size = MINSIZE
- blocks = bytes = 0
- while size <= self.cachelimit:
- head = self.avail[size]
- node = head.next
- count = 0
- while node is not head:
- count += 1
- node = node.next
- if count:
- print "%d:%d" % (size, count),
- blocks += count
- bytes += count*size
- size += size
- print "-- %d, %d" % (bytes, blocks)
-
-def roundup(size):
- k = MINSIZE
- while k < size:
- k += k
- return k
-
-class SimpleAllocator:
-
- def __init__(self, arenasize):
- self.arenasize = arenasize
- self.avail = BlockNode(None, 0, 0) # Weird: empty block as list head
- self.rover = self.avail
- node = BlockNode(None, arenasize, 0)
- node.linkbefore(self.avail)
- self.taglo = {0: node}
- self.taghi = {arenasize: node}
- # Allocator statistics
- self.nallocs = 0
- self.nfrees = 0
- self.allocloops = 0
- self.freebytes = arenasize
- self.freeblocks = 1
- self.allocbytes = 0
- self.allocblocks = 0
-
- def report(self):
- print ("NA=%d AL=%d NF=%d ABy=%d ABl=%d FBy=%d FBl=%d" %
- (self.nallocs, self.allocloops,
- self.nfrees,
- self.allocbytes, self.allocblocks,
- self.freebytes, self.freeblocks))
-
- def alloc(self, size):
- self.nallocs += 1
- # First fit algorithm
- rover = stop = self.rover
- while 1:
- self.allocloops += 1
- if rover.size >= size:
- break
- rover = rover.next
- if rover is stop:
- return None # We went round the list without finding space
- if rover.size == size:
- self.rover = rover.next
- rover.unlink()
- del self.taglo[rover.addr]
- del self.taghi[rover.addr + size]
- self.freeblocks -= 1
- self.allocblocks += 1
- self.freebytes -= size
- self.allocbytes += size
- return rover
- # Take space from the beginning of the roving pointer
- assert rover.size > size
- node = BlockNode(None, size, rover.addr)
- del self.taglo[rover.addr]
- rover.size -= size
- rover.addr += size
- self.taglo[rover.addr] = rover
- #self.freeblocks += 0 # No change here
- self.allocblocks += 1
- self.freebytes -= size
- self.allocbytes += size
- return node
-
- def free(self, node):
- self.nfrees += 1
- self.freeblocks += 1
- self.allocblocks -= 1
- self.freebytes += node.size
- self.allocbytes -= node.size
- node.linkbefore(self.avail)
- self.taglo[node.addr] = node
- self.taghi[node.addr + node.size] = node
- x = self.taghi.get(node.addr)
- if x is not None:
- # Merge x into node
- x.unlink()
- self.freeblocks -= 1
- del self.taglo[x.addr]
- del self.taghi[x.addr + x.size]
- del self.taglo[node.addr]
- node.addr = x.addr
- node.size += x.size
- self.taglo[node.addr] = node
- x = self.taglo.get(node.addr + node.size)
- if x is not None:
- # Merge x into node
- x.unlink()
- self.freeblocks -= 1
- del self.taglo[x.addr]
- del self.taghi[x.addr + x.size]
- del self.taghi[node.addr + node.size]
- node.size += x.size
- self.taghi[node.addr + node.size] = node
- # It's possible that either one of the merges above invalidated
- # the rover.
- # It's simplest to simply reset the rover to the newly freed block.
- self.rover = node
-
- def dump(self, msg=""):
- if msg:
- print msg,
- count = 0
- bytes = 0
- node = self.avail.next
- while node is not self.avail:
- bytes += node.size
- count += 1
- node = node.next
- print count, "free blocks,", bytes, "free bytes"
- self.report()
-
-class BlockNode(Node):
-
- __slots__ = ['addr']
-
- def __init__(self, oid, size, addr):
- Node.__init__(self, oid, size)
- self.addr = addr
-
-def testallocator(factory=BuddyAllocator):
- # Run one of Knuth's experiments as a test
- import random
- import heapq # This only runs with Python 2.3, folks :-)
- reportfreq = 100
- cachelimit = 2**17
- cache = factory(cachelimit)
- queue = []
- T = 0
- blocks = 0
- while T < 5000:
- while queue and queue[0][0] <= T:
- time, node = heapq.heappop(queue)
- assert time == T
- ##print "free addr=%d, size=%d" % (node.addr, node.size)
- cache.free(node)
- blocks -= 1
- size = random.randint(100, 2000)
- lifetime = random.randint(1, 100)
- node = cache.alloc(size)
- if node is None:
- print "out of mem"
- cache.dump("T=%4d: %d blocks;" % (T, blocks))
- break
- else:
- ##print "alloc addr=%d, size=%d" % (node.addr, node.size)
- blocks += 1
- heapq.heappush(queue, (T + lifetime, node))
- T = T+1
- if T % reportfreq == 0:
- cache.dump("T=%4d: %d blocks;" % (T, blocks))
-
-def hitrate(loads, hits):
- return "%5.1f%%" % (100.0 * hits / max(1, loads))
-
-def duration(secs):
- mm, ss = divmod(secs, 60)
- hh, mm = divmod(mm, 60)
- if hh:
- return "%d:%02d:%02d" % (hh, mm, ss)
- if mm:
- return "%d:%02d" % (mm, ss)
- return "%d" % ss
-
-def addcommas(n):
- sign, s = '', str(n)
- if s[0] == '-':
- sign, s = '-', s[1:]
- i = len(s) - 3
- while i > 0:
- s = s[:i] + ',' + s[i:]
- i -= 3
- return sign + s
-
-import random
-
-def maybe(f, p=0.5):
- if random.random() < p:
- f()
-
-#############################################################################
-# Thor-like eviction scheme.
-#
-# The cache keeps a list of all objects, and uses a travelling pointer
-# to decay the worth of objects over time.
-
-class ThorNode(Node):
-
- __slots__ = ['worth']
-
- def __init__(self, oid, size, worth=None):
- Node.__init__(self, oid, size)
- self.worth = worth
-
-class ThorListHead(Node):
- def __init__(self):
- Node.__init__(self, 0, 0)
- self.next = self.prev = self
-
-class ThorSimulation(Simulation):
-
- extras = "evicts", "trips"
-
- def __init__(self, cachelimit):
- Simulation.__init__(self, cachelimit)
-
- # Maximum total of object sizes we keep in cache.
- self.maxsize = cachelimit
- # Current total of object sizes in cache.
- self.currentsize = 0
-
- # A worth byte maps to a set of all objects with that worth.
- # This is cheap to keep updated, and makes finding low-worth
- # objects for eviction trivial (just march over the worthsets
- # list, in order).
- self.worthsets = [Set() for dummy in range(256)]
-
- # We keep a circular list of all objects in cache. currentobj
- # walks around it forever. Each time _tick() is called, the
- # worth of currentobj is decreased, basically by shifting
- # right 1, and currentobj moves on to the next object. When
- # an object is first inserted, it enters the list right before
- # currentobj. When an object is accessed, its worth is
- # increased by or'ing in 0x80. This scheme comes from the
- # Thor system, and is an inexpensive way to account for both
- # recency and frequency of access: recency is reflected in
- # the leftmost bit set, and frequency by how many bits are
- # set.
- #
- # Note: because evictions are interleaved with ticks,
- # unlinking an object is tricky, lest we evict currentobj. The
- # class _unlink method takes care of this properly.
- self.listhead = ThorListHead()
- self.currentobj = self.listhead
-
- # Map an object.oid to its ThorNode.
- self.oid2object = {}
-
- self.total_evicts = self.total_trips = 0
-
- # Unlink object from the circular list, taking care not to lose
- # track of the current object. Always call this instead of
- # invoking obj.unlink() directly.
- def _unlink(self, obj):
- assert obj is not self.listhead
- if obj is self.currentobj:
- self.currentobj = obj.next
- obj.unlink()
-
- # Change obj.worth to newworth, maintaining invariants.
- def _change_worth(self, obj, newworth):
- if obj.worth != newworth:
- self.worthsets[obj.worth].remove(obj)
- obj.worth = newworth
- self.worthsets[newworth].add(obj)
-
- def add(self, object):
- assert object.oid not in self.oid2object
- self.oid2object[object.oid] = object
-
- newsize = self.currentsize + object.size
- if newsize > self.maxsize:
- self._evictbytes(newsize - self.maxsize)
- self.currentsize += object.size
- object.linkbefore(self.currentobj)
-
- if object.worth is None:
- # Give smaller objects higher initial worth. This favors kicking
- # out unreferenced large objects before kicking out unreferenced
- # small objects. On real life traces, this is a significant
- # win for the hit rate.
- object.worth = 32 - int(round(math.log(object.size, 2)))
- self.worthsets[object.worth].add(object)
-
- # Decrease the worth of the current object, and advance the
- # current object.
- def _tick(self):
- c = self.currentobj
- if c is self.listhead:
- c = c.next
- if c is self.listhead: # list is empty
- return
- self.total_trips += 1
- self.trips += 1
- self._change_worth(c, (c.worth + 1) >> 1)
- self.currentobj = c.next
-
- def access(self, oid):
- self._tick()
- obj = self.oid2object.get(oid)
- if obj is None:
- return None
- self._change_worth(obj, obj.worth | 0x80)
- return obj
-
- # Evict objects of least worth first, until at least nbytes bytes
- # have been freed.
- def _evictbytes(self, nbytes):
- for s in self.worthsets:
- while s:
- if nbytes <= 0:
- return
- obj = s.pop()
- nbytes -= obj.size
- self._evictobj(obj)
-
- def _evictobj(self, obj):
- self.currentsize -= obj.size
- self.worthsets[obj.worth].discard(obj)
- del self.oid2object[obj.oid]
- self._unlink(obj)
-
- self.evicts += 1
- self.total_evicts += 1
-
- def _evict_without_bumping_evict_stats(self, obj):
- self._evictobj(obj)
- self.evicts -= 1
- self.total_evicts -= 1
-
- # Simulator overrides from here on.
-
- def restart(self):
- # Reset base class
- Simulation.restart(self)
- # Reset additional per-run statistics
- self.evicts = self.trips = 0
-
- def write(self, oid, size):
- obj = self.oid2object.get(oid)
- worth = None
- if obj is not None:
- worth = obj.worth
- self._evict_without_bumping_evict_stats(obj)
- self.add(ThorNode(oid, size, worth))
-
- def load(self, oid, size):
- if self.access(oid) is not None:
- self.hits += 1
- self.total_hits += 1
- else:
- self.write(oid, size)
-
- def inval(self, oid):
- obj = self.oid2object.get(oid)
- if obj is not None:
- self.invals += 1
- self.total_invals += 1
- self._evict_without_bumping_evict_stats(obj)
-
- # Take the "x" off to see additional stats after each restart period.
- def xreport(self):
- Simulation.report(self)
- print 'non-empty worth sets', sum(map(bool, self.worthsets)),
- print 'objects', len(self.oid2object),
- print 'size', self.currentsize
-
-#############################################################################
-# Perfection: What if the cache were unbounded, and never forgot anything?
-# This simulator answers that question directly; the cache size parameter
-# isn't used.
-
-class UnboundedSimulation(Simulation):
-
- extraname = 'evicts' # for some reason we *have* to define >= 1 extra
-
- def __init__(self, cachelimit):
- Simulation.__init__(self, cachelimit)
- self.oids = Set()
- self.evicts = self.total_evicts = 0
-
- def write(self, oid, size):
- self.oids.add(oid)
-
- def load(self, oid, size):
- if oid in self.oids:
- self.hits += 1
- self.total_hits += 1
- else:
- self.oids.add(oid)
-
- def inval(self, oid):
- if oid in self.oids:
- self.invals += 1
- self.total_invals += 1
- self.oids.remove(oid)
-
-if __name__ == "__main__":
- sys.exit(main())
Deleted: ZODB/trunk/src/ZODB/scripts/stats.py
===================================================================
--- ZODB/trunk/src/ZODB/scripts/stats.py 2010-07-12 14:37:39 UTC (rev 114632)
+++ ZODB/trunk/src/ZODB/scripts/stats.py 2010-07-12 14:37:40 UTC (rev 114633)
@@ -1,387 +0,0 @@
-##############################################################################
-#
-# Copyright (c) 2001, 2002 Zope Foundation and Contributors.
-# All Rights Reserved.
-#
-# This software is subject to the provisions of the Zope Public License,
-# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution.
-# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED
-# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
-# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS
-# FOR A PARTICULAR PURPOSE
-#
-##############################################################################
-"""Trace file statistics analyzer.
-
-Usage: stats.py [-h] [-i interval] [-q] [-s] [-S] [-v] [-X] tracefile
--h: print histogram of object load frequencies
--i: summarizing interval in minutes (default 15; max 60)
--q: quiet; don't print summaries
--s: print histogram of object sizes
--S: don't print statistics
--v: verbose; print each record
--X: enable heuristic checking for misaligned records: oids > 2**32
- will be rejected; this requires the tracefile to be seekable
-"""
-
-"""File format:
-
-Each record is 26 bytes, plus a variable number of bytes to store an oid,
-with the following layout. Numbers are big-endian integers.
-
-Offset Size Contents
-
-0 4 timestamp (seconds since 1/1/1970)
-4 3 data size, in 256-byte increments, rounded up
-7 1 code (see below)
-8 2 object id length
-10 8 start tid
-18 8 end tid
-26 variable object id
-
-The code at offset 7 packs three fields:
-
-Mask bits Contents
-
-0x80 1 set if there was a non-empty version string
-0x7e 6 function and outcome code
-0x01 1 current cache file (0 or 1)
-
-The "current cache file" bit is no longer used; it refers to a 2-file
-cache scheme used before ZODB 3.3.
-
-The function and outcome codes are documented in detail at the end of
-this file in the 'explain' dictionary. Note that the keys there (and
-also the arguments to _trace() in ClientStorage.py) are 'code & 0x7e',
-i.e. the low bit is always zero.
-"""
-
-import sys
-import time
-import getopt
-import struct
-from types import StringType
-
-def usage(msg):
- print >> sys.stderr, msg
- print >> sys.stderr, __doc__
-
-def main():
- # Parse options
- verbose = False
- quiet = False
- dostats = True
- print_size_histogram = False
- print_histogram = False
- interval = 15*60 # Every 15 minutes
- heuristic = False
- try:
- opts, args = getopt.getopt(sys.argv[1:], "hi:qsSvX")
- except getopt.error, msg:
- usage(msg)
- return 2
- for o, a in opts:
- if o == '-h':
- print_histogram = True
- elif o == "-i":
- interval = int(60 * float(a))
- if interval <= 0:
- interval = 60
- elif interval > 3600:
- interval = 3600
- elif o == "-q":
- quiet = True
- verbose = False
- elif o == "-s":
- print_size_histogram = True
- elif o == "-S":
- dostats = False
- elif o == "-v":
- verbose = True
- elif o == '-X':
- heuristic = True
- else:
- assert False, (o, opts)
-
- if len(args) != 1:
- usage("exactly one file argument required")
- return 2
- filename = args[0]
-
- # Open file
- if filename.endswith(".gz"):
- # Open gzipped file
- try:
- import gzip
- except ImportError:
- print >> sys.stderr, "can't read gzipped files (no module gzip)"
- return 1
- try:
- f = gzip.open(filename, "rb")
- except IOError, msg:
- print >> sys.stderr, "can't open %s: %s" % (filename, msg)
- return 1
- elif filename == '-':
- # Read from stdin
- f = sys.stdin
- else:
- # Open regular file
- try:
- f = open(filename, "rb")
- except IOError, msg:
- print >> sys.stderr, "can't open %s: %s" % (filename, msg)
- return 1
-
- rt0 = time.time()
- bycode = {} # map code to count of occurrences
- byinterval = {} # map code to count in current interval
- records = 0 # number of trace records read
- versions = 0 # number of trace records with versions
- datarecords = 0 # number of records with dlen set
- datasize = 0L # sum of dlen across records with dlen set
- oids = {} # map oid to number of times it was loaded
- bysize = {} # map data size to number of loads
- bysizew = {} # map data size to number of writes
- total_loads = 0
- t0 = None # first timestamp seen
- te = None # most recent timestamp seen
- h0 = None # timestamp at start of current interval
- he = None # timestamp at end of current interval
- thisinterval = None # generally te//interval
- f_read = f.read
- unpack = struct.unpack
- FMT = ">iiH8s8s"
- FMT_SIZE = struct.calcsize(FMT)
- assert FMT_SIZE == 26
- # Read file, gathering statistics, and printing each record if verbose.
- try:
- while 1:
- r = f_read(FMT_SIZE)
- if len(r) < FMT_SIZE:
- break
- ts, code, oidlen, start_tid, end_tid = unpack(FMT, r)
- if ts == 0:
- # Must be a misaligned record caused by a crash.
- if not quiet:
- print "Skipping 8 bytes at offset", f.tell() - FMT_SIZE
- f.seek(f.tell() - FMT_SIZE + 8)
- continue
- oid = f_read(oidlen)
- if len(oid) < oidlen:
- break
- records += 1
- if t0 is None:
- t0 = ts
- thisinterval = t0 // interval
- h0 = he = ts
- te = ts
- if ts // interval != thisinterval:
- if not quiet:
- dumpbyinterval(byinterval, h0, he)
- byinterval = {}
- thisinterval = ts // interval
- h0 = ts
- he = ts
- dlen, code = code & 0x7fffff00, code & 0xff
- if dlen:
- datarecords += 1
- datasize += dlen
- if code & 0x80:
- version = 'V'
- versions += 1
- else:
- version = '-'
- code &= 0x7e
- bycode[code] = bycode.get(code, 0) + 1
- byinterval[code] = byinterval.get(code, 0) + 1
- if dlen:
- if code & 0x70 == 0x20: # All loads
- bysize[dlen] = d = bysize.get(dlen) or {}
- d[oid] = d.get(oid, 0) + 1
- elif code & 0x70 == 0x50: # All stores
- bysizew[dlen] = d = bysizew.get(dlen) or {}
- d[oid] = d.get(oid, 0) + 1
- if verbose:
- print "%s %02x %s %016x %016x %c %s" % (
- time.ctime(ts)[4:-5],
- code,
- oid_repr(oid),
- U64(start_tid),
- U64(end_tid),
- version,
- dlen and str(dlen) or "")
- if code & 0x70 == 0x20:
- oids[oid] = oids.get(oid, 0) + 1
- total_loads += 1
- elif code == 0x00: # restart
- if not quiet:
- dumpbyinterval(byinterval, h0, he)
- byinterval = {}
- thisinterval = ts // interval
- h0 = he = ts
- if not quiet:
- print time.ctime(ts)[4:-5],
- print '='*20, "Restart", '='*20
- except KeyboardInterrupt:
- print "\nInterrupted. Stats so far:\n"
-
- end_pos = f.tell()
- f.close()
- rte = time.time()
- if not quiet:
- dumpbyinterval(byinterval, h0, he)
-
- # Error if nothing was read
- if not records:
- print >> sys.stderr, "No records processed"
- return 1
-
- # Print statistics
- if dostats:
- print
- print "Read %s trace records (%s bytes) in %.1f seconds" % (
- addcommas(records), addcommas(end_pos), rte-rt0)
- print "Versions: %s records used a version" % addcommas(versions)
- 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" % (
- addcommas(datarecords),
- 100.0 * datarecords / records,
- datasize / 1024.0 / datarecords)
- print "Hit rate: %.1f%% (load hits / loads)" % hitrate(bycode)
- print
- codes = bycode.keys()
- codes.sort()
- print "%13s %4s %s" % ("Count", "Code", "Function (action)")
- for code in codes:
- print "%13s %02x %s" % (
- addcommas(bycode.get(code, 0)),
- code,
- explain.get(code) or "*** unknown code ***")
-
- # Print histogram.
- if print_histogram:
- print
- print "Histogram of object load frequency"
- total = len(oids)
- print "Unique oids: %s" % addcommas(total)
- print "Total loads: %s" % addcommas(total_loads)
- s = addcommas(total)
- width = max(len(s), len("objects"))
- fmt = "%5d %" + str(width) + "s %5.1f%% %5.1f%% %5.1f%%"
- hdr = "%5s %" + str(width) + "s %6s %6s %6s"
- print hdr % ("loads", "objects", "%obj", "%load", "%cum")
- cum = 0.0
- for binsize, count in histogram(oids):
- obj_percent = 100.0 * count / total
- load_percent = 100.0 * count * binsize / total_loads
- cum += load_percent
- print fmt % (binsize, addcommas(count),
- obj_percent, load_percent, cum)
-
- # Print size histogram.
- if print_size_histogram:
- print
- print "Histograms of object sizes"
- print
- dumpbysize(bysizew, "written", "writes")
- dumpbysize(bysize, "loaded", "loads")
-
-def dumpbysize(bysize, how, how2):
- print
- print "Unique sizes %s: %s" % (how, addcommas(len(bysize)))
- print "%10s %6s %6s" % ("size", "objs", how2)
- sizes = bysize.keys()
- sizes.sort()
- for size in sizes:
- loads = 0
- for n in bysize[size].itervalues():
- loads += n
- print "%10s %6d %6d" % (addcommas(size),
- len(bysize.get(size, "")),
- loads)
-
-def dumpbyinterval(byinterval, h0, he):
- loads = hits = 0
- for code in byinterval:
- if code & 0x70 == 0x20:
- n = byinterval[code]
- loads += n
- if code in (0x22, 0x26):
- hits += n
- if not loads:
- return
- if loads:
- hr = 100.0 * hits / loads
- else:
- hr = 0.0
- print "%s-%s %10s loads, %10s hits,%5.1f%% hit rate" % (
- time.ctime(h0)[4:-8], time.ctime(he)[14:-8],
- addcommas(loads), addcommas(hits), hr)
-
-def hitrate(bycode):
- loads = hits = 0
- for code in bycode:
- if code & 0x70 == 0x20:
- n = bycode[code]
- loads += n
- if code in (0x22, 0x26):
- hits += n
- if loads:
- return 100.0 * hits / loads
- else:
- return 0.0
-
-def histogram(d):
- bins = {}
- for v in d.itervalues():
- bins[v] = bins.get(v, 0) + 1
- L = bins.items()
- L.sort()
- return L
-
-def U64(s):
- return struct.unpack(">Q", s)[0]
-
-def oid_repr(oid):
- if isinstance(oid, StringType) and len(oid) == 8:
- return '%16x' % U64(oid)
- else:
- return repr(oid)
-
-def addcommas(n):
- sign, s = '', str(n)
- if s[0] == '-':
- sign, s = '-', s[1:]
- i = len(s) - 3
- while i > 0:
- s = s[:i] + ',' + s[i:]
- i -= 3
- return sign + s
-
-explain = {
- # The first hex digit shows the operation, the second the outcome.
- # If the second digit is in "02468" then it is a 'miss'.
- # If it is in "ACE" then it is a 'hit'.
-
- 0x00: "_setup_trace (initialization)",
-
- 0x10: "invalidate (miss)",
- 0x1A: "invalidate (hit, version)",
- 0x1C: "invalidate (hit, saving non-current)",
- # 0x1E can occur during startup verification.
- 0x1E: "invalidate (hit, discarding current or non-current)",
-
- 0x20: "load (miss)",
- 0x22: "load (hit)",
- 0x24: "load (non-current, miss)",
- 0x26: "load (non-current, hit)",
-
- 0x50: "store (version)",
- 0x52: "store (current, non-version)",
- 0x54: "store (non-current)",
- }
-
-if __name__ == "__main__":
- sys.exit(main())
Modified: ZODB/trunk/src/ZODB/tests/util.py
===================================================================
--- ZODB/trunk/src/ZODB/tests/util.py 2010-07-12 14:37:39 UTC (rev 114632)
+++ ZODB/trunk/src/ZODB/tests/util.py 2010-07-12 14:37:40 UTC (rev 114633)
@@ -138,3 +138,20 @@
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
+
More information about the Zodb-checkins
mailing list