[Checkins] SVN: relstorage/trunk/ Added more logging during zodbconvert to show that something is
Maurits van Rees
m.van.rees at zestsoftware.nl
Fri Jan 7 12:00:31 EST 2011
Log message for revision 119443:
Added more logging during zodbconvert to show that something is
happening and give an indication of how far along the process is.
(This is a merge of the logging-improvement part of the 1.4.0-fastimport branch.)
Changed:
U relstorage/trunk/CHANGES.txt
U relstorage/trunk/relstorage/adapters/schema.py
U relstorage/trunk/relstorage/storage.py
U relstorage/trunk/relstorage/zodbconvert.py
-=-
Modified: relstorage/trunk/CHANGES.txt
===================================================================
--- relstorage/trunk/CHANGES.txt 2011-01-07 15:31:55 UTC (rev 119442)
+++ relstorage/trunk/CHANGES.txt 2011-01-07 17:00:30 UTC (rev 119443)
@@ -2,6 +2,9 @@
Next Release
------------
+- Added more logging during zodbconvert to show that something is
+ happening and give an indication of how far along the process is.
+
- Fixed a missing import in the blob cache cleanup code.
1.5.0a1 (2010-10-21)
Modified: relstorage/trunk/relstorage/adapters/schema.py
===================================================================
--- relstorage/trunk/relstorage/adapters/schema.py 2011-01-07 15:31:55 UTC (rev 119442)
+++ relstorage/trunk/relstorage/adapters/schema.py 2011-01-07 17:00:30 UTC (rev 119443)
@@ -13,6 +13,7 @@
##############################################################################
"""Database schema installers
"""
+import logging
from relstorage.adapters.interfaces import ISchemaInstaller
from ZODB.POSException import StorageError
from zope.interface import implements
@@ -20,6 +21,7 @@
import time
relstorage_op_version = '1.5'
+log = logging.getLogger("relstorage")
history_preserving_schema = """
@@ -830,14 +832,20 @@
existent = set(self.list_tables(cursor))
todo = list(self.all_tables)
todo.reverse()
+ log.info("Checking tables: %r", todo)
for table in todo:
+ log.info("Considering table %s", table)
if table.startswith('temp_'):
continue
if table in existent:
+ log.info("Deleting table %s...", table)
cursor.execute("DELETE FROM %s" % table)
+ log.info("Done deleting tables.")
script = filter_script(self.init_script, self.database_name)
if script:
+ log.info("Running init script.")
self.runner.run_script(cursor, script)
+ log.info("Done running init script.")
self.connmanager.open_and_call(callback)
def drop_all(self):
Modified: relstorage/trunk/relstorage/storage.py
===================================================================
--- relstorage/trunk/relstorage/storage.py 2011-01-07 15:31:55 UTC (rev 119442)
+++ relstorage/trunk/relstorage/storage.py 2011-01-07 17:00:30 UTC (rev 119443)
@@ -1320,8 +1320,13 @@
def copyTransactionsFrom(self, other):
# adapted from ZODB.blob.BlobStorageMixin
+ begin_time = time.time()
+ txnum = 0
+ tx_size = 0
+ num_txns = len(list(other.iterator()))
for trans in other.iterator():
self.tpc_begin(trans, trans.tid, trans.status)
+ num_txn_records = 0
for record in trans:
blobfilename = None
if self.blobhelper is not None:
@@ -1342,10 +1347,29 @@
else:
self.restore(record.oid, record.tid, record.data,
'', record.data_txn, trans)
+ num_txn_records += 1
+ try:
+ tx_size += len(record.data)
+ except TypeError:
+ # data is probably None
+ pass
+ txnum += 1
+ tx_end = time.time()
+ pct_complete = (txnum / float(num_txns)) * 100
+ if pct_complete < 10:
+ pct_complete = ' %1.2f%%' % pct_complete
+ elif pct_complete < 100:
+ pct_complete = ' %1.2f%%' % pct_complete
+ rate = (tx_size / float(1024 * 1024)) / (tx_end - begin_time)
self.tpc_vote(trans)
self.tpc_finish(trans)
+ log.info("Restored tid %d,%5d records | %1.3f MB/s (%6d/%6d,%s)",
+ u64(trans.tid), num_txn_records, rate, txnum, num_txns,
+ pct_complete)
+ return txnum, tx_size, tx_end - begin_time
+
# The propagate_invalidations flag implements the old
# invalidation polling API and is not otherwise used. Set to a
# false value, it tells the Connection not to propagate object
Modified: relstorage/trunk/relstorage/zodbconvert.py
===================================================================
--- relstorage/trunk/relstorage/zodbconvert.py 2011-01-07 15:31:55 UTC (rev 119442)
+++ relstorage/trunk/relstorage/zodbconvert.py 2011-01-07 17:00:30 UTC (rev 119443)
@@ -17,6 +17,7 @@
See README.txt for details.
"""
+import logging
import optparse
from persistent.TimeStamp import TimeStamp
from StringIO import StringIO
@@ -35,7 +36,12 @@
</schema>
"""
+log = logging.getLogger("relstorage.zodbconvert")
+logging.basicConfig(
+ level=logging.INFO,
+ format="%(asctime)s %(levelname)s:%(name)s: %(message)s")
+
def storage_has_data(storage):
i = storage.iterator()
try:
@@ -70,38 +76,53 @@
source = config.source.open()
destination = config.destination.open()
- write("Storages opened successfully.\n")
+ #write("Storages opened successfully.\n")
+ log.info("Storages opened successfully.")
if options.dry_run:
- write("Dry run mode: not changing the destination.\n")
+ #write("Dry run mode: not changing the destination.\n")
+ log.info("Dry run mode: not changing the destination.")
if storage_has_data(destination):
- write("Warning: the destination storage has data\n")
+ #write("Warning: the destination storage has data\n")
+ log.warning("The destination storage has data.")
count = 0
for txn in source.iterator():
write('%s user=%s description=%s\n' % (
TimeStamp(txn.tid), txn.user, txn.description))
count += 1
- write("Would copy %d transactions.\n" % count)
+ #write("Would copy %d transactions.\n" % count)
+ log.info("Would copy %d transactions.", count)
else:
if options.clear:
+ log.info("Clearing old data...")
if hasattr(destination, 'zap_all'):
destination.zap_all()
else:
msg = ("Error: no API is known for clearing this type "
"of storage. Use another method.")
sys.exit(msg)
+ log.info("Done clearing old data.")
if storage_has_data(destination):
msg = "Error: the destination storage has data. Try --clear."
sys.exit(msg)
- destination.copyTransactionsFrom(source)
+ log.info("Started copying transactions...")
+ log.info("This will take long...")
+ #destination.copyTransactionsFrom(source)
+ num_txns, size, elapsed = destination.copyTransactionsFrom(source)
+ log.info("Done copying transactions.")
+ log.info("Closing up...")
source.close()
destination.close()
- write('All transactions copied successfully.\n')
+ rate = (size/float(1024*1024)) / elapsed
+ #write('All %d transactions copied successfully in %4.1f minutes at %1.3fmB/s.\n' %
+ # (num_txns, elapsed/60, rate))
+ log.info('All %d transactions copied successfully in %4.1f minutes at %1.3fmB/s.',
+ num_txns, elapsed/60, rate)
if __name__ == '__main__':
More information about the checkins
mailing list