Commit 8e540a65 authored by Jim Fulton's avatar Jim Fulton

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.
parent 5fad0539
......@@ -26,6 +26,13 @@ Bugs fixed
https://bugs.launchpad.net/zodb/+bug/143237
- There were numerous bugs in the ZEO cache tracing and analysys code.
Cache simulation, while not perfect, seems to be much more accurate
now than it was before.
The ZEO cache trace statistics and simulation scripts have been
given more descriptive names and moved to the ZEO scripts package.
3.10.0b1 (2010-05-18)
=====================
......
......@@ -379,6 +379,7 @@ class ClientCache(object):
# Close the underlying file. No methods accessing the cache should be
# used after this.
def close(self):
self._unsetup_trace()
f = self.f
self.f = None
if f is not None:
......@@ -726,6 +727,10 @@ class ClientCache(object):
# self._tracefile. If not, or we can't write to the trace file, disable
# tracing by setting self._trace to a dummy function, and set
# self._tracefile to None.
_tracefile = None
def _trace(self, *a, **kw):
pass
def _setup_trace(self, path):
_tracefile = None
if path and os.environ.get("ZEO_CACHE_TRACE"):
......@@ -738,7 +743,6 @@ class ClientCache(object):
logger.info("opened tracefile %r", tfn)
if _tracefile is None:
self._trace = lambda *a, **k: None
return
now = time.time
......@@ -747,7 +751,7 @@ class ClientCache(object):
# The first hex digit shows the operation, the second the outcome.
# This method has been carefully tuned to be as fast as possible.
# Note: when tracing is disabled, this method is hidden by a dummy.
encoded = (dlen + 255) & 0x7fffff00 | code
encoded = (dlen << 8) + code
if tid is None:
tid = z64
if end_tid is None:
......@@ -762,8 +766,15 @@ class ClientCache(object):
raise
self._trace = _trace
self._tracefile = _tracefile
_trace(0x00)
def _unsetup_trace(self):
if self._tracefile is not None:
del self._trace
self._tracefile.close()
del self._tracefile
def sync(f):
f.flush()
......
This diff is collapsed.
......@@ -66,7 +66,9 @@ def usage(msg):
print >> sys.stderr, msg
print >> sys.stderr, __doc__
def main():
def main(args=None):
if args is None:
args = sys.argv[1:]
# Parse options
verbose = False
quiet = False
......@@ -76,7 +78,7 @@ def main():
interval = 15*60 # Every 15 minutes
heuristic = False
try:
opts, args = getopt.getopt(sys.argv[1:], "hi:qsSvX")
opts, args = getopt.getopt(args, "hi:qsSvX")
except getopt.error, msg:
usage(msg)
return 2
......@@ -154,6 +156,8 @@ def main():
FMT_SIZE = struct.calcsize(FMT)
assert FMT_SIZE == 26
# Read file, gathering statistics, and printing each record if verbose.
print ' '*16, "%7s %7s %7s %7s" % ('loads', 'hits', 'inv(h)', 'writes'),
print 'hitrate'
try:
while 1:
r = f_read(FMT_SIZE)
......@@ -182,7 +186,7 @@ def main():
thisinterval = ts // interval
h0 = ts
he = ts
dlen, code = code & 0x7fffff00, code & 0xff
dlen, code = (code & 0x7fffff00) >> 8, code & 0xff
if dlen:
datarecords += 1
datasize += dlen
......@@ -245,10 +249,10 @@ def main():
print "First time: %s" % time.ctime(t0)
print "Last time: %s" % time.ctime(te)
print "Duration: %s seconds" % addcommas(te-t0)
print "Data recs: %s (%.1f%%), average size %.1f KB" % (
print "Data recs: %s (%.1f%%), average size %d bytes" % (
addcommas(datarecords),
100.0 * datarecords / records,
datasize / 1024.0 / datarecords)
datasize / datarecords)
print "Hit rate: %.1f%% (load hits / loads)" % hitrate(bycode)
print
codes = bycode.keys()
......@@ -303,22 +307,27 @@ def dumpbysize(bysize, how, how2):
loads)
def dumpbyinterval(byinterval, h0, he):
loads = hits = 0
loads = hits = invals = writes = 0
for code in byinterval:
if code & 0x70 == 0x20:
if code & 0x20:
n = byinterval[code]
loads += n
if code in (0x22, 0x26):
hits += n
if not loads:
return
elif code & 0x40:
writes += byinterval[code]
elif code & 0x10:
if code != 0x10:
invals += byinterval[code]
if loads:
hr = 100.0 * hits / loads
hr = "%5.1f%%" % (100.0 * hits / loads)
else:
hr = 0.0
print "%s-%s %10s loads, %10s hits,%5.1f%% hit rate" % (
hr = 'n/a'
print "%s-%s %7s %7s %7s %7s %7s" % (
time.ctime(h0)[4:-8], time.ctime(he)[14:-8],
addcommas(loads), addcommas(hits), hr)
loads, hits, invals, writes, hr)
def hitrate(bycode):
loads = hits = 0
......
This diff is collapsed.
This diff is collapsed.
......@@ -138,3 +138,20 @@ def store(storage, oid, value='x', serial=ZODB.utils.z64):
storage.store(oid, serial, value, '', t)
storage.tpc_vote(t)
storage.tpc_finish(t)
def mess_with_time(test=None, globs=None, now=1278864701.5):
now = [now]
def faux_time():
now[0] += 1
return now[0]
if test is None and globs is not None:
# sigh
faux_time.globs = globs
test = faux_time
import time
zope.testing.setupstack.register(test, setattr, time, 'time', time.time)
time.time = faux_time
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment