[Checkins] SVN: zc.FileStorage/trunk/ - Improved use of posix_fadvise (where available)
Jim Fulton
jim at zope.com
Wed Mar 10 15:05:58 EST 2010
Log message for revision 109900:
- Improved use of posix_fadvise (where available)
- Provided an option to rest between transactions to try to avoid
excessive stress on the storage server.
- Provided some progress logging (every GIG) in the pack log.
Changed:
A zc.FileStorage/trunk/CHANGES.txt
U zc.FileStorage/trunk/src/zc/FileStorage/__init__.py
U zc.FileStorage/trunk/src/zc/FileStorage/tests.py
-=-
Added: zc.FileStorage/trunk/CHANGES.txt
===================================================================
--- zc.FileStorage/trunk/CHANGES.txt (rev 0)
+++ zc.FileStorage/trunk/CHANGES.txt 2010-03-10 20:05:57 UTC (rev 109900)
@@ -0,0 +1,17 @@
+
+1.1.0 (1010-03-10)
+==================
+
+- Improved use of posix_fadvise (where available)
+
+- Provided an option to rest between transactions to try to avoid
+ excessive stress on the storage server.
+
+- Provided some progress logging (every GIG) in the pack log.
+
+1.0.0 (2009-11-06)
+==================
+
+Updated to work with ZODB 3.9.
+
+Removed GC support, since that is now provided by zc.zodbdgc.
Property changes on: zc.FileStorage/trunk/CHANGES.txt
___________________________________________________________________
Added: svn:eol-style
+ native
Modified: zc.FileStorage/trunk/src/zc/FileStorage/__init__.py
===================================================================
--- zc.FileStorage/trunk/src/zc/FileStorage/__init__.py 2010-03-10 18:43:31 UTC (rev 109899)
+++ zc.FileStorage/trunk/src/zc/FileStorage/__init__.py 2010-03-10 20:05:57 UTC (rev 109900)
@@ -17,6 +17,7 @@
import os
import subprocess
import sys
+import time
from ZODB.FileStorage.format import FileStorageFormatter, CorruptedDataError
from ZODB.utils import p64, u64, z64
@@ -27,14 +28,25 @@
import ZODB.fsIndex
import ZODB.TimeStamp
-def packer(storage, referencesf, stop, gc):
- return FileStoragePacker(storage, stop).pack()
+GIG = 1<<30
+def meta_packer(sleep):
+ def packer(storage, referencesf, stop, gc):
+ return FileStoragePacker(storage, stop, sleep).pack()
+ return packer
+
+packer = meta_packer(0)
+packer1 = meta_packer(1)
+packer2 = meta_packer(2)
+packer4 = meta_packer(3)
+packer8 = meta_packer(4)
+
class FileStoragePacker(FileStorageFormatter):
- def __init__(self, storage, stop):
+ def __init__(self, storage, stop, sleep=0):
self.storage = storage
self._name = path = storage._file.name
+ self.sleep = sleep
# We open our own handle on the storage so that much of pack can
# proceed in parallel. It's important to close this file at every
@@ -71,6 +83,7 @@
size = self.file_end,
syspath = sys.path,
blob_dir = self.storage.blob_dir,
+ sleep = self.sleep,
))
for name in 'error', 'log':
name = self._name+'.pack'+name
@@ -158,6 +171,7 @@
if release is not None:
release()
+ start_time = time.time()
output_tpos = output.tell()
copier.setTxnPos(output_tpos)
output.write(th.asString())
@@ -194,6 +208,7 @@
index.update(tindex)
tindex.clear()
+ time.sleep((time.time()-start_time)*self.sleep)
if acquire is not None:
acquire()
@@ -243,7 +258,7 @@
try:
packer = zc.FileStorage.PackProcess(%(path)r, %(stop)r, %(size)r,
- %(blob_dir)r)
+ %(blob_dir)r, %(sleep)s)
packer.pack()
except Exception, v:
logging.exception('packing')
@@ -258,7 +273,7 @@
class PackProcess(FileStoragePacker):
- def __init__(self, path, stop, current_size, blob_dir):
+ def __init__(self, path, stop, current_size, blob_dir, sleep):
self._name = path
# We open our own handle on the storage so that much of pack can
# proceed in parallel. It's important to close this file at every
@@ -281,9 +296,12 @@
self.ltid = z64
self._freecache = _freefunc(self._file)
- logging.info('packing to %s',
- ZODB.TimeStamp.TimeStamp(self._stop))
+ self.sleep = sleep
+ logging.info('packing to %s, sleep %s',
+ ZODB.TimeStamp.TimeStamp(self._stop),
+ self.sleep)
+
def _read_txn_header(self, pos, tid=None):
self._freecache(pos)
return FileStoragePacker._read_txn_header(self, pos, tid)
@@ -321,14 +339,17 @@
os.fsync(output.fileno())
output.close()
self._file.close()
+ logging.info('packscript done')
def buildPackIndex(self, stop, file_end):
index = ZODB.fsIndex.fsIndex()
pos = 4L
packed = True
+ log_pos = pos
while pos < file_end:
+ start_time = time.time()
th = self._read_txn_header(pos)
if th.tid > stop:
break
@@ -358,6 +379,12 @@
tlen, th.tlen)
pos += 8
+ if pos - log_pos > GIG:
+ logging.info("read %s" % pos)
+ log_pos = pos
+
+ time.sleep((time.time()-start_time)*self.sleep)
+
return packed, index, pos
def copyToPacktime(self, packpos, index, output):
@@ -368,7 +395,10 @@
pack_blobs = self.pack_blobs
is_blob_record = ZODB.blob.is_blob_record
+ log_pos = pos
+
while pos < packpos:
+ start_time = time.time()
th = self._read_txn_header(pos)
new_tpos = 0L
tend = pos + th.tlen
@@ -456,6 +486,12 @@
pos += 8
+ if pos - log_pos > GIG:
+ logging.info("read %s" % pos)
+ log_pos = pos
+
+ time.sleep((time.time()-start_time)*self.sleep)
+
return new_index, new_pos
def fetchDataViaBackpointer(self, oid, back):
@@ -470,13 +506,22 @@
data, tid = self._loadBackTxn(oid, back, 0)
return data
- def copyFromPacktime(self, input_pos, file_end, output, index):
- while input_pos < file_end:
- input_pos = self._copyNewTrans(input_pos, output, index)
+ def copyFromPacktime(self, pos, file_end, output, index):
+
+ log_pos = pos
+ while pos < file_end:
+ start_time = time.time()
+ pos = self._copyNewTrans(pos, output, index)
self._freeoutputcache(output.tell())
- return input_pos
+ if pos - log_pos > GIG:
+ logging.info("read %s" % pos)
+ log_pos = pos
+ time.sleep((time.time()-start_time)*self.sleep)
+ return pos
+
+
def _freefunc(f):
# Return an posix_fadvise-based cache freeer.
Modified: zc.FileStorage/trunk/src/zc/FileStorage/tests.py
===================================================================
--- zc.FileStorage/trunk/src/zc/FileStorage/tests.py 2010-03-10 18:43:31 UTC (rev 109899)
+++ zc.FileStorage/trunk/src/zc/FileStorage/tests.py 2010-03-10 20:05:57 UTC (rev 109900)
@@ -113,6 +113,187 @@
blob_dir = 'blobs'
+
+time_hack_template = """
+now = 1268166473.0
+import time
+
+time_time, time_sleep = time.time, time.sleep
+
+time.sleep(1) # Slow things down a bit to give the test time to commit
+
+def faux_time():
+ global now
+ now += 1
+ return now
+
+def faux_sleep(x):
+ logging.info('sleep '+`x`)
+
+time.time, time.sleep = faux_time, faux_sleep
+"""
+
+GIG_hack_template = """
+
+import sys
+
+sys.path[:] = %(syspath)r
+
+import zc.FileStorage
+zc.FileStorage.GIG = 100
+
+"""
+
+def test_pack_sleep():
+ """
+Make sure that sleep is being called. :)
+
+Mess with time -- there should be infrastructure for this!
+
+ >>> exec(time_hack_template)
+ >>> time.sleep = time_sleep
+
+ >>> import threading, transaction, shutil, ZODB.FileStorage, zc.FileStorage
+ >>> fs = ZODB.FileStorage.FileStorage('data.fs',
+ ... packer=zc.FileStorage.packer1)
+ >>> db = ZODB.DB(fs)
+ >>> conn = db.open()
+ >>> for i in range(5):
+ ... conn.root()[i] = conn.root().__class__()
+ ... transaction.commit()
+ >>> pack_time = time.time()
+ >>> for i in range(5):
+ ... conn.root()[i].x = 1
+ ... transaction.commit()
+
+ >>> pack_script_template = zc.FileStorage.pack_script_template
+ >>> zc.FileStorage.pack_script_template = (
+ ... time_hack_template + GIG_hack_template + pack_script_template)
+ >>> thread = threading.Thread(target=fs.pack, args=(pack_time, now))
+ >>> thread.start()
+ >>> for i in range(100):
+ ... if os.path.exists('data.fs.packscript'):
+ ... break
+ ... time.sleep(0.01)
+ >>> def faux_sleep(x):
+ ... print 'sleep '+`x`
+ >>> time.sleep = faux_sleep
+ >>> conn.root().x = 1
+ >>> transaction.commit()
+ >>> thread.join()
+ sleep 1.0
+
+ >>> fs.close()
+ >>> print open('data.fs.packlog').read(), # doctest: +NORMALIZE_WHITESPACE
+ 2010-03-09 15:27:55,000 root INFO packing to 2010-03-09 20:28:06.000000,
+ sleep 1
+ 2010-03-09 15:27:57,000 root INFO read 162
+ 2010-03-09 15:27:59,000 root INFO sleep 2.0
+ 2010-03-09 15:28:01,000 root INFO read 411
+ 2010-03-09 15:28:03,000 root INFO sleep 2.0
+ 2010-03-09 15:28:05,000 root INFO read 680
+ 2010-03-09 15:28:07,000 root INFO sleep 2.0
+ 2010-03-09 15:28:09,000 root INFO read 968
+ 2010-03-09 15:28:11,000 root INFO sleep 2.0
+ 2010-03-09 15:28:13,000 root INFO read 1275
+ 2010-03-09 15:28:15,000 root INFO sleep 2.0
+ 2010-03-09 15:28:17,000 root INFO read 1601
+ 2010-03-09 15:28:19,000 root INFO sleep 2.0
+ 2010-03-09 15:28:21,000 root INFO initial scan 6 objects at 1601
+ 2010-03-09 15:28:22,000 root INFO copy to pack time
+ 2010-03-09 15:28:24,000 root INFO read 162
+ 2010-03-09 15:28:26,000 root INFO sleep 2.0
+ 2010-03-09 15:28:28,000 root INFO read 411
+ 2010-03-09 15:28:30,000 root INFO sleep 2.0
+ 2010-03-09 15:28:32,000 root INFO read 680
+ 2010-03-09 15:28:34,000 root INFO sleep 2.0
+ 2010-03-09 15:28:36,000 root INFO read 968
+ 2010-03-09 15:28:38,000 root INFO sleep 2.0
+ 2010-03-09 15:28:40,000 root INFO read 1275
+ 2010-03-09 15:28:42,000 root INFO sleep 2.0
+ 2010-03-09 15:28:44,000 root INFO read 1601
+ 2010-03-09 15:28:46,000 root INFO sleep 2.0
+ 2010-03-09 15:28:47,000 root INFO copy from pack time
+ 2010-03-09 15:28:51,000 root INFO sleep 1.0
+ 2010-03-09 15:28:52,000 root INFO read 1737
+ 2010-03-09 15:28:54,000 root INFO sleep 5.0
+ 2010-03-09 15:28:58,000 root INFO sleep 1.0
+ 2010-03-09 15:28:59,000 root INFO read 1873
+ 2010-03-09 15:29:01,000 root INFO sleep 5.0
+ 2010-03-09 15:29:05,000 root INFO sleep 1.0
+ 2010-03-09 15:29:06,000 root INFO read 2009
+ 2010-03-09 15:29:08,000 root INFO sleep 5.0
+ 2010-03-09 15:29:12,000 root INFO sleep 1.0
+ 2010-03-09 15:29:13,000 root INFO read 2145
+ 2010-03-09 15:29:15,000 root INFO sleep 5.0
+ 2010-03-09 15:29:19,000 root INFO sleep 1.0
+ 2010-03-09 15:29:20,000 root INFO read 2281
+ 2010-03-09 15:29:22,000 root INFO sleep 5.0
+ 2010-03-09 15:29:23,000 root INFO packscript done
+
+ >>> time.sleep = time_sleep
+ >>> time.time = time_time
+
+Now do it all again with a longer sleep:
+
+ >>> shutil.copyfile('data.fs.old', 'data.fs')
+ >>> fs = ZODB.FileStorage.FileStorage('data.fs',
+ ... packer=zc.FileStorage.packer2)
+ >>> fs.pack(pack_time, now)
+ >>> print open('data.fs.packlog').read(), # doctest: +NORMALIZE_WHITESPACE
+ 2010-03-09 15:27:55,000 root INFO packing to 2010-03-09 20:28:06.000000,
+ sleep 2
+ 2010-03-09 15:27:57,000 root INFO read 162
+ 2010-03-09 15:27:59,000 root INFO sleep 4.0
+ 2010-03-09 15:28:01,000 root INFO read 411
+ 2010-03-09 15:28:03,000 root INFO sleep 4.0
+ 2010-03-09 15:28:05,000 root INFO read 680
+ 2010-03-09 15:28:07,000 root INFO sleep 4.0
+ 2010-03-09 15:28:09,000 root INFO read 968
+ 2010-03-09 15:28:11,000 root INFO sleep 4.0
+ 2010-03-09 15:28:13,000 root INFO read 1275
+ 2010-03-09 15:28:15,000 root INFO sleep 4.0
+ 2010-03-09 15:28:17,000 root INFO read 1601
+ 2010-03-09 15:28:19,000 root INFO sleep 4.0
+ 2010-03-09 15:28:21,000 root INFO initial scan 6 objects at 1601
+ 2010-03-09 15:28:22,000 root INFO copy to pack time
+ 2010-03-09 15:28:24,000 root INFO read 162
+ 2010-03-09 15:28:26,000 root INFO sleep 4.0
+ 2010-03-09 15:28:28,000 root INFO read 411
+ 2010-03-09 15:28:30,000 root INFO sleep 4.0
+ 2010-03-09 15:28:32,000 root INFO read 680
+ 2010-03-09 15:28:34,000 root INFO sleep 4.0
+ 2010-03-09 15:28:36,000 root INFO read 968
+ 2010-03-09 15:28:38,000 root INFO sleep 4.0
+ 2010-03-09 15:28:40,000 root INFO read 1275
+ 2010-03-09 15:28:42,000 root INFO sleep 4.0
+ 2010-03-09 15:28:44,000 root INFO read 1601
+ 2010-03-09 15:28:46,000 root INFO sleep 4.0
+ 2010-03-09 15:28:47,000 root INFO copy from pack time
+ 2010-03-09 15:28:51,000 root INFO sleep 2.0
+ 2010-03-09 15:28:52,000 root INFO read 1737
+ 2010-03-09 15:28:54,000 root INFO sleep 10.0
+ 2010-03-09 15:28:58,000 root INFO sleep 2.0
+ 2010-03-09 15:28:59,000 root INFO read 1873
+ 2010-03-09 15:29:01,000 root INFO sleep 10.0
+ 2010-03-09 15:29:05,000 root INFO sleep 2.0
+ 2010-03-09 15:29:06,000 root INFO read 2009
+ 2010-03-09 15:29:08,000 root INFO sleep 10.0
+ 2010-03-09 15:29:12,000 root INFO sleep 2.0
+ 2010-03-09 15:29:13,000 root INFO read 2145
+ 2010-03-09 15:29:15,000 root INFO sleep 10.0
+ 2010-03-09 15:29:19,000 root INFO sleep 2.0
+ 2010-03-09 15:29:20,000 root INFO read 2281
+ 2010-03-09 15:29:22,000 root INFO sleep 10.0
+ 2010-03-09 15:29:26,000 root INFO sleep 2.0
+ 2010-03-09 15:29:27,000 root INFO read 2514
+ 2010-03-09 15:29:29,000 root INFO sleep 10.0
+ 2010-03-09 15:29:30,000 root INFO packscript done
+
+ >>> zc.FileStorage.pack_script_template = pack_script_template
+
+ """
+
def test_suite():
suite = unittest.TestSuite()
suite.addTest(unittest.makeSuite(ZCFileStorageTests, "check"))
@@ -121,4 +302,7 @@
'blob_packing.txt',
setUp=setupstack.setUpDirectory, tearDown=setupstack.tearDown,
))
+ suite.addTest(doctest.DocTestSuite(
+ setUp=setupstack.setUpDirectory, tearDown=setupstack.tearDown,
+ ))
return suite
More information about the checkins
mailing list