def test__p_mtime_w_serial(self):
from persistent.timestamp import TimeStamp
WHEN_TUPLE = (2011, 2, 15, 13, 33, 27.5)
ts = TimeStamp(*WHEN_TUPLE)
inst, jar, OID = self._makeOneWithJar()
inst._p_serial = ts.raw()
self.assertEqual(inst._p_mtime, ts.timeTime())
def test__p_mtime_w_serial(self):
from persistent.timestamp import TimeStamp
WHEN_TUPLE = (2011, 2, 15, 13, 33, 27.5)
ts = TimeStamp(*WHEN_TUPLE)
inst, jar, OID = self._makeOneWithJar()
inst._p_serial = ts.raw()
self.assertEqual(inst._p_mtime, ts.timeTime())
def _get_mtime(self):
# The C implementation automatically unghostifies the object
# when _p_mtime is accessed.
self._p_activate()
self._p_accessed()
serial = _OGA(self, '_Persistent__serial')
if serial is not None:
ts = TimeStamp(serial)
return ts.timeTime()
def _get_mtime(self):
# The C implementation automatically unghostifies the object
# when _p_mtime is accessed.
self._p_activate()
self._p_accessed()
serial = _OGA(self, '_Persistent__serial')
if serial is not None:
ts = TimeStamp(serial)
return ts.timeTime()
def get_cache_modification_time_for_stream(self):
max_tid = 0
for key in self.local_client:
parts = key.split(':')
if len(parts) != 4:
continue
tid = int(parts[2])
max_tid = max(tid, max_tid)
if max_tid:
tid_str = p64(max_tid)
ts = TimeStamp(tid_str)
return ts.timeTime()
def get_cache_modification_time_for_stream(self):
max_tid = 0
for key in self.local_client:
parts = key.split(':')
if len(parts) != 4:
continue
tid = int(parts[2])
max_tid = max(tid, max_tid)
if max_tid:
tid_str = p64(max_tid)
ts = TimeStamp(tid_str)
return ts.timeTime()
def history(self, oid, version=None, size=1, filter=None):
# pylint:disable=unused-argument,too-many-locals
cursor = self.load_connection.cursor
oid_int = bytes8_to_int64(oid)
try:
rows = self.adapter.dbiter.iter_object_history(cursor, oid_int)
except KeyError:
raise POSKeyError(oid)
res = []
for tid_int, username, description, extension, length in rows:
tid = int64_to_8bytes(tid_int)
if extension:
d = loads(extension)
else:
d = {}
d.update({
"time": TimeStamp(tid).timeTime(),
"user_name": username or b'',
"description": description or b'',
"tid": tid,
"version": '',
"size": length,
"rs_tid_int": tid_int,
"rs_oid_int": oid_int,
})
if filter is None or filter(d):
res.append(d)
if size is not None and len(res) >= size:
break
return res
def undoLog(self, first=0, last=-20, filter=None):
if last < 0:
last = first - last
# use a private connection to ensure the most current results
with self.load_connection.isolated_connection() as cursor:
tx_iter = self.adapter.dbiter.iter_transactions(cursor)
i = 0
res = []
for tx in tx_iter:
tid = int64_to_8bytes(tx.tid_int)
# Note that user and desc are schizophrenic. The transaction
# interface specifies that they are a Python str, *probably*
# meaning bytes. But code in the wild and the ZODB test suite
# sets them as native strings, meaning unicode on Py3. OTOH, the
# test suite checks that this method *returns* them as bytes!
# This is largely cleaned up with transaction 2.0/ZODB 5, where the storage
# interface is defined in terms of bytes only.
d = {
'id': base64_encodebytes(tid)[:-1], # pylint:disable=deprecated-method
'time': TimeStamp(tid).timeTime(),
'user_name': tx.username or b'',
'description': tx.description or b'',
}
if tx.extension:
d.update(loads(tx.extension))
if filter is None or filter(d):
if i >= first:
res.append(d)
i += 1
if i >= last:
break
return res
def checkPackWithGCOnDestinationAfterRestore(self):
raises = self.assertRaises
closing = self._closing
__traceback_info__ = self._storage, self._dst
db = closing(DB(self._storage))
conn = closing(db.open())
root = conn.root()
root.obj = obj1 = MinPO(1)
txn = transaction.get()
txn.note(u'root -> obj')
txn.commit()
root.obj.obj = obj2 = MinPO(2)
txn = transaction.get()
txn.note(u'root -> obj -> obj')
txn.commit()
del root.obj
txn = transaction.get()
txn.note(u'root -X->')
txn.commit()
storage_last_tid = conn._storage.lastTransaction()
self.assertEqual(storage_last_tid, root._p_serial)
# Now copy the transactions to the destination
self._dst.copyTransactionsFrom(self._storage)
self.assertEqual(self._dst.lastTransaction(), storage_last_tid)
# If the source storage is a history-free storage, all
# of the transactions are now marked as packed in the
# destination storage. To trigger a pack, we have to
# add another transaction to the destination that is
# not packed.
db2 = closing(DB(self._dst))
tx_manager = transaction.TransactionManager(explicit=True)
conn2 = closing(db2.open(tx_manager))
txn = tx_manager.begin()
root2 = conn2.root()
root2.extra = 0
txn.note(u'root.extra = 0')
txn.commit()
dest_last_tid = conn2._storage.lastTransaction()
self.assertGreater(dest_last_tid, storage_last_tid)
self.assertEqual(dest_last_tid, root2._p_serial)
# Now pack the destination.
from ZODB.utils import u64 as bytes8_to_int64
if IRelStorage.providedBy(self._dst):
packtime = bytes8_to_int64(storage_last_tid)
else:
from persistent.timestamp import TimeStamp
packtime = TimeStamp(dest_last_tid).timeTime() + 2
self._dst.pack(packtime, referencesf)
# And check to see that the root object exists, but not the other
# objects.
__traceback_info__ += (packtime,)
_data, _serial = self._dst.load(root._p_oid, '')
raises(KeyError, self._dst.load, obj1._p_oid, '')
raises(KeyError, self._dst.load, obj2._p_oid, '')
def lock_database_and_choose_next_tid(self, cursor, username, description,
extension):
self.locker.hold_commit_lock(cursor, ensure_current=True)
# Choose a transaction ID.
#
# Base the transaction ID on the current time, but ensure that
# the tid of this transaction is greater than any existing
# tid.
last_tid = self.txncontrol.get_tid(cursor)
now = time.time()
stamp = timestamp_at_unixtime(now)
stamp = stamp.laterThan(TimeStamp(int64_to_8bytes(last_tid)))
tid = stamp.raw()
tid_int = bytes8_to_int64(tid)
self.txncontrol.add_transaction(cursor, tid_int, username, description,
extension)
logger.log(TRACE, "Picked next tid locally: %s", tid_int)
return tid_int
def undoLog(self, first=0, last=-20, filter=None):
# pylint:disable=too-many-locals
if last < 0:
last = first - last
# use a private connection to ensure the most current results
adapter = self.adapter
conn, cursor = adapter.connmanager.open()
try:
rows = adapter.dbiter.iter_transactions(cursor)
i = 0
res = []
for tid_int, user, desc, ext in rows:
tid = int64_to_8bytes(tid_int)
# Note that user and desc are schizophrenic. The transaction
# interface specifies that they are a Python str, *probably*
# meaning bytes. But code in the wild and the ZODB test suite
# sets them as native strings, meaning unicode on Py3. OTOH, the
# test suite checks that this method *returns* them as bytes!
# This is largely cleaned up with transaction 2.0/ZODB 5, where the storage
# interface is defined in terms of bytes only.
d = {
'id': base64_encodebytes(tid)[:-1], # pylint:disable=deprecated-method
'time': TimeStamp(tid).timeTime(),
'user_name': user or b'',
'description': desc or b'',
}
if ext:
d.update(loads(ext))
if filter is None or filter(d):
if i >= first:
res.append(d)
i += 1
if i >= last:
break
return res
finally:
adapter.connmanager.close(conn, cursor)
def test_current_time(self, now=None):
from persistent.timestamp import TimeStamp
from relstorage._util import int64_to_8bytes
if now is None:
now = time.time()
storage = self._storage
ts_now = timestamp_at_unixtime(now)
expected_tid_int = bytes8_to_int64(ts_now.raw())
__traceback_info__ = now, now % 60.0, time.gmtime(
now), ts_now, expected_tid_int
cursor = storage._load_connection.cursor
cursor.execute('CALL make_tid_for_epoch(%s, @tid)', (now, ))
cursor.execute('SELECT @tid')
tid, = cursor.fetchall()[0]
tid_as_timetime = TimeStamp(int64_to_8bytes(tid)).timeTime()
__traceback_info__ += (tid_as_timetime - ts_now.timeTime(), )
self.assertEqual(tid, expected_tid_int)
def timestamp_at_unixtime(now):
"""
Return a :class:`persistent.timestamp.TimeStamp` for the moment
given by *now* (a float giving seconds since the epoch).
"""
# ``now`` is a float (double precision.). We extract the seconds
# value using ``now % 60.0``. But performing a modulus operation
# on it tends to invent precision that we do not really have.
#
# For example, given the timestamp ``1564178539.353595``, the
# correct value for seconds is obviously ``19.353595``. But Python
# tends to answer ``19.35359501838684``. When the TimeStamp
# constructor takes that double precision value and applies *more*
# arithmetic to it to set the bias, the results get worse: we get
# ``1385384294.4`` when we should get ``1385384293.0838187``.
#
# If we're comparing with a system that doesn't use exactly IEEE double
# arithmetic to calculate the seconds value, this can lead to wrong answers.
gmtime = time.gmtime(now)
seconds = now % 60.0
return TimeStamp(*(gmtime[:5] + (seconds, )))
def _check_tid_after_load(self,
oid_int,
actual_tid_int,
expect_tid_int=None):
"""Verify the tid of an object loaded from the database is sane."""
if actual_tid_int > self.current_tid:
# Strangely, the database just gave us data from a future
# transaction. We can't give the data to ZODB because that
# would be a consistency violation. However, the cause is
# hard to track down, so issue a ReadConflictError and
# hope that the application retries successfully.
msg = ("Got data for OID 0x%(oid_int)x from "
"future transaction %(actual_tid_int)d (%(got_ts)s). "
"Current transaction is %(current_tid)d (%(current_ts)s)." %
{
'oid_int': oid_int,
'actual_tid_int': actual_tid_int,
'current_tid': self.current_tid,
'got_ts': str(TimeStamp(p64(actual_tid_int))),
'current_ts': str(TimeStamp(p64(self.current_tid))),
})
raise ReadConflictError(msg)
if expect_tid_int is not None and actual_tid_int != expect_tid_int:
# Uh-oh, the cache is inconsistent with the database.
# We didn't get a TID from the future, but it's not what we
# had in our delta_after0 map, which means...we missed a change
# somewhere.
#
# Possible causes:
#
# - The database MUST provide a snapshot view for each
# session; this error can occur if that requirement is
# violated. For example, MySQL's MyISAM engine is not
# sufficient for the object_state table because MyISAM
# can not provide a snapshot view. (InnoDB is
# sufficient.)
#
# - (Similar to the last one.) Using too low of a
# isolation level for the database connection and
# viewing unrelated data.
#
# - Something could be writing to the database out
# of order, such as a version of RelStorage that
# acquires a different commit lock.
#
# - A software bug. In the past, there was a subtle bug
# in after_poll() that caused it to ignore the
# transaction order, leading it to sometimes put the
# wrong tid in delta_after*.
#
# - Restarting a load connection at a future point we hadn't
# actually polled to, such that our current_tid is out of sync
# with the connection's *actual* viewable tid?
cp0, cp1 = self.checkpoints
msg = ("Detected an inconsistency "
"between the RelStorage cache and the database "
"while loading an object using the delta_after0 dict. "
"Please verify the database is configured for "
"ACID compliance and that all clients are using "
"the same commit lock. "
"(oid_int=%(oid_int)r, expect_tid_int=%(expect_tid_int)r, "
"actual_tid_int=%(actual_tid_int)r, "
"current_tid=%(current_tid)r, cp0=%(cp0)r, cp1=%(cp1)r, "
"len(delta_after0)=%(lda0)r, len(delta_after1)=%(lda1)r, "
"pid=%(pid)r, thread_ident=%(thread_ident)r)" % {
'oid_int': oid_int,
'expect_tid_int': expect_tid_int,
'actual_tid_int': actual_tid_int,
'current_tid': self.current_tid,
'cp0': cp0,
'cp1': cp1,
'lda0': len(self.delta_after0),
'lda1': len(self.delta_after1),
'pid': os.getpid(),
'thread_ident': threading.current_thread(),
})
# We reset ourself as if we hadn't polled, and hope the transient
# error gets retried in a working, consistent view.
self._reset(msg)
def readable_tid_repr(tid):
result = tid_repr(tid)
if isinstance(tid, bytes) and len(tid) == 8:
result = "%s %s" % (result, TimeStamp(tid))
return result
def newTid(old):
t = time.time()
ts = TimeStamp(*time.gmtime(t)[:5]+(t%60,))
if old is not None:
ts = ts.laterThan(TimeStamp(old))
return ts.raw()
def doit(srcdb, dstdb, options):
outfp = options.outfp
profilep = options.profilep
verbose = options.verbose
# some global information
largest_pickle = 0
largest_txn_in_size = 0
largest_txn_in_objects = 0
total_pickle_size = 0
total_object_count = 0
# Ripped from BaseStorage.copyTransactionsFrom()
ts = None
ok = True
prevrevids = {}
counter = 0
skipper = 0
if options.timestamps:
print("%4s. %26s %6s %8s %5s %5s %5s %5s %5s" % (
"NUM", "TID AS TIMESTAMP", "OBJS", "BYTES",
# Does anybody know what these times mean?
"t4-t0", "t1-t0", "t2-t1", "t3-t2", "t4-t3"))
else:
print("%4s. %20s %6s %8s %6s %6s %6s %6s %6s" % (
"NUM", "TRANSACTION ID", "OBJS", "BYTES",
# Does anybody know what these times mean?
"t4-t0", "t1-t0", "t2-t1", "t3-t2", "t4-t3"))
for txn in srcdb.iterator():
skipper += 1
if skipper <= options.skiptxn:
continue
counter += 1
if counter > options.maxtxn >= 0:
break
tid = txn.tid
if ts is None:
ts = TimeStamp(tid)
else:
t = TimeStamp(tid)
if t <= ts:
if ok:
print((
'Time stamps are out of order %s, %s' % (ts, t)), file=sys.stderr)
ok = False
ts = t.laterThan(ts)
tid = ts.raw()
else:
ts = t
if not ok:
print((
'Time stamps are back in order %s' % t), file=sys.stderr)
ok = True
if verbose > 1:
print(ts)
prof = None
if profilep and (counter % 100) == 0:
prof = profile.Profile()
objects = 0
size = 0
newrevids = RevidAccumulator()
t0 = time.time()
dstdb.tpc_begin(txn, tid, txn.status)
t1 = time.time()
for r in txn:
oid = r.oid
objects += 1
thissize = len(r.data)
size += thissize
if thissize > largest_pickle:
largest_pickle = thissize
if verbose > 1:
if not r.version:
vstr = 'norev'
else:
vstr = r.version
print(utils.U64(oid), vstr, len(r.data))
oldrevid = prevrevids.get(oid, utils.z64)
result = dstdb.store(oid, oldrevid, r.data, r.version, txn)
newrevids.store(oid, result)
t2 = time.time()
result = dstdb.tpc_vote(txn)
t3 = time.time()
newrevids.tpc_vote(result)
prevrevids.update(newrevids.get_dict())
# Profile every 100 transactions
if prof:
prof.runcall(dstdb.tpc_finish, txn)
else:
dstdb.tpc_finish(txn)
t4 = time.time()
# record the results
if objects > largest_txn_in_objects:
largest_txn_in_objects = objects
if size > largest_txn_in_size:
largest_txn_in_size = size
if options.timestamps:
tidstr = str(TimeStamp(tid))
format = "%4d. %26s %6d %8d %5.3f %5.3f %5.3f %5.3f %5.3f"
else:
tidstr = utils.U64(tid)
format = "%4d. %20s %6d %8d %6.4f %6.4f %6.4f %6.4f %6.4f"
print(format % (skipper, tidstr, objects, size,
t4-t0, t1-t0, t2-t1, t3-t2, t4-t3), file=outfp)
total_pickle_size += size
total_object_count += objects
if prof:
prof.create_stats()
fp = open('profile-%02d.txt' % (counter / 100), 'wb')
marshal.dump(prof.stats, fp)
fp.close()
print("Largest pickle: %8d" % largest_pickle, file=outfp)
print("Largest transaction: %8d" % largest_txn_in_size, file=outfp)
print("Largest object count: %8d" % largest_txn_in_objects, file=outfp)
print("Total pickle size: %14d" % total_pickle_size, file=outfp)
print("Total object count: %8d" % total_object_count, file=outfp)
def __pre_pack(self, t, referencesf):
logger.info("pack: beginning pre-pack")
# In 2019, Unix timestamps look like
# 1564006806.0
# While 64-bit integer TIDs for the same timestamp look like
# 275085010696509852
#
# Multiple TIDs can map to a single Unix timestamp.
# For example, the 9 integers between 275085010624927044 and
# 275085010624927035 all map to 1564006804.9999998.
#
# Therefore, Unix timestamps are ambiguous, especially if we're committing
# multiple transactions rapidly (within the resolution of the underlying TID
# clock).
# This ambiguity mostly matters for unit tests, where we do commit rapidly.
#
# To help them out, we accept 64-bit integer TIDs to specify an exact
# transaction to pack to.
# We also allow None or a negative number to mean "current committed transaction".
if t is None:
t = -1
if t > 275085010696509852:
# Must be a TID.
# Turn it back into a time.time() for later logging
ts = TimeStamp(int64_to_8bytes(t))
logger.debug(
"Treating requested pack time %s as TID meaning %s",
t, ts
)
best_pack_tid_int = t
t = ts.timeTime()
elif t < 0 or t >= time.time():
# Packing for the current time or in the future means to pack
# to the lastest commit in the database. This matters if not all
# machine clocks are synchronized.
best_pack_tid_int = MAX_TID - 1
else:
# Find the latest commit before or at the pack time.
# Note that several TIDs will fit in the resolution of a time.time(),
# so this is slightly ambiguous.
requested_pack_ts = TimeStamp(*time.gmtime(t)[:5] + (t % 60,))
requested_pack_tid = requested_pack_ts.raw()
requested_pack_tid_int = bytes8_to_int64(requested_pack_tid)
best_pack_tid_int = requested_pack_tid_int
tid_int = self.packundo.choose_pack_transaction(best_pack_tid_int)
if tid_int is None:
logger.debug("all transactions before %s have already "
"been packed", time.ctime(t))
return
s = time.ctime(TimeStamp(int64_to_8bytes(tid_int)).timeTime())
logger.info("Analyzing transactions committed %s or before (TID %d)",
s, tid_int)
# In pre_pack, the adapter fills tables with
# information about what to pack. The adapter
# must not actually pack anything yet.
def get_references(state):
"""Return an iterable of the set of OIDs the given state refers to."""
if not state:
return ()
return {bytes8_to_int64(oid) for oid in referencesf(state)}
self.packundo.pre_pack(tid_int, get_references)
logger.info("pack: pre-pack complete")
return tid_int
def main(argv=None):
# pylint:disable=too-many-branches,too-many-statements
if argv is None:
argv = sys.argv
parser = argparse.ArgumentParser(description=__doc__)
parser.add_argument(
"--dry-run",
dest="dry_run",
action="store_true",
default=False,
help="Attempt to open both storages, then explain what would be done.")
parser.add_argument(
"--clear",
dest="clear",
action="store_true",
default=False,
help="Clear the contents of the destination storage before copying."
" Only works if the destination is a RelStorage."
" WARNING: use this only if you are certain the destination has no useful data."
)
parser.add_argument(
"--incremental",
dest="incremental",
action="store_true",
help="Assume the destination contains a partial copy of the source "
"and resume copying from the last transaction. WARNING: no "
"effort is made to verify that the destination holds the same "
"transaction data before this point! Use at your own risk. ")
parser.add_argument("config_file", type=argparse.FileType('r'))
options = parser.parse_args(argv[1:])
logging.basicConfig(
level=logging.INFO,
format="%(asctime)s [%(name)s] %(levelname)s %(message)s")
source, destination = open_storages(options)
def cleanup_and_exit(exit_msg=None):
source.close()
destination.close()
if exit_msg:
sys.exit(msg)
log.info("Storages opened successfully.")
if options.incremental:
assert hasattr(destination, 'lastTransaction'), (
"Error: no API is known for determining the last committed "
"transaction of the destination storage. Aborting "
"conversion.")
if not storage_has_data(destination):
log.warning(
"Destination empty, start conversion from the beginning.")
else:
# This requires that the storage produce a valid (not z64) value before
# anything is loaded with it.
last_tid = destination.lastTransaction()
if isinstance(last_tid, bytes):
# This *should* be a byte string.
last_tid = u64(last_tid)
next_tid = p64(last_tid + 1)
# Compensate for the RelStorage bug(?) and get a reusable iterator
# that starts where we want it to. There's no harm in wrapping it for
# other sources like FileStorage too.
source = _DefaultStartStorageIteration(source, next_tid)
log.info("Resuming ZODB copy from %s", readable_tid_repr(next_tid))
if options.dry_run:
log.info("Dry run mode: not changing the destination.")
if storage_has_data(destination):
log.warning("The destination storage has data.")
count = 0
for txn in source.iterator():
log.info('%s user=%s description=%s', TimeStamp(txn.tid), txn.user,
txn.description)
count += 1
log.info("Would copy %d transactions.", count)
cleanup_and_exit()
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.")
cleanup_and_exit(msg)
log.info("Done clearing old data.")
if storage_has_data(destination) and not options.incremental:
msg = "Error: the destination storage has data. Try --clear."
cleanup_and_exit(msg)
destination.copyTransactionsFrom(source)
cleanup_and_exit()
def _makeC(self, *args, **kwargs):
from persistent.timestamp import TimeStamp
return TimeStamp(*args, **kwargs)
def _get_mtime(self):
if self.__serial is not None:
ts = TimeStamp(self.__serial)
return ts.timeTime()
def _get_mtime(self):
if self.__serial is not None:
ts = TimeStamp(self.__serial)
return ts.timeTime()