Simplify MVCC by determining transaction start time using lastTransac…

…tion.

This implements: #50

Rather than watching invalidations, simply use 1 + the storages
lastTransaction, which is equivalent to but much simpler than waiting
for the first invalidation after a transaction starts.

More importantly, it means we can always use loadBefore and get away
from load.  We no longer have to worry about ordering of invalidations
and load() results.

Much thanks to NEO for pointing the way toward this simplification!

Implementing this initially caused a deadlock, because DB.open()
called Connection.open() while holding a database lock and
Connection.open() now calls IStotage.lastTransaction(), which acquires a
storage lock. (It's not clear that lastTransaction() really needs a
storage lock.)  Meanwhile, IStotage.tpc_finish() calls a DB function
that requires the DB lock while holding the storage lock.  Fixing this
required moving the call to Connection.open() outside the region where
the DB lock was held.

To debug the problem above, I greatly improved lock-debugging
support. Now all of the ZODB code imports Lock, RLock and Condition
from ZODB.utils. If the DEBUG_LOCKING is set to a non-empty value,
then these are wrapped in such a way that debugging information is
printed as they are used. This made spotting the nature of the
deadlock easier.

Of course, a change this basic broke lots of tests. Most of the
breakage arises from the fact that connections now call
lastTransaction on storages at transaction boundaries.  Lots of tests
didn't clean up databases and connections properly.  I fixed many
tests, but ultimately gave up and added some extra cleanup code that
violated transaction-manager underware (and the underware's privates)
to clear transaction synchonizers in test setup and tear-down.  I plan
to add a transaction manager API for this and to use it in a
subsequent PR.

This tests makes database and connection hygiene a bit more important,
especially for tests, because a connection will continue to interact
with storages if it isn't properly closed, which can lead to errors if
the storage is closed.  I chose not to swallow these errors in
Connection, choosing rather to clean up tests.

The thread debugging and test changes make this PR larger than I would
have liked. Apologies in advance to the reviewers.

src/ZODB/ActivityMonitor.py

@@ -12,12 +12,12 @@
 #
 ##############################################################################
 """ZODB transfer activity monitoring
+"""
 
-$Id$"""
-
-import threading
 import time
 
+from . import utils
+
 
 class ActivityMonitor:
     """ZODB load/store activity monitor
@@ -31,7 +31,7 @@ class ActivityMonitor:
     def __init__(self, history_length=3600):
         self.history_length = history_length  # Number of seconds
         self.log = []                     # [(time, loads, stores)]
-        self.trim_lock = threading.Lock()
+        self.trim_lock = utils.Lock()
 
     def closedConnection(self, conn):
         log = self.log
@@ -42,7 +42,7 @@ def closedConnection(self, conn):
 
     def trim(self, now):
         self.trim_lock.acquire()
-        
+
         log = self.log
         cutoff = now - self.history_length
         n = 0
@@ -51,7 +51,7 @@ def trim(self, now):
             n = n + 1
         if n:
             del log[:n]
-        
+
         self.trim_lock.release()
 
     def setHistoryLength(self, history_length):

src/ZODB/BaseStorage.py

@@ -18,7 +18,6 @@
 """
 from __future__ import print_function
 
-import threading
 import time
 import logging
 import sys
@@ -28,10 +27,10 @@
 from persistent.TimeStamp import TimeStamp
 
 import ZODB.interfaces
-from ZODB import POSException
-from ZODB.utils import z64, oid_repr, byte_ord, byte_chr
-from ZODB.UndoLogCompatible import UndoLogCompatible
-from ZODB._compat import dumps, _protocol, py2_hasattr
+from . import POSException, utils
+from .utils import z64, oid_repr, byte_ord, byte_chr
+from .UndoLogCompatible import UndoLogCompatible
+from ._compat import dumps, _protocol, py2_hasattr
 
 log = logging.getLogger("ZODB.BaseStorage")
 
@@ -85,8 +84,8 @@ def __init__(self, name, base=None):
         log.debug("create storage %s", self.__name__)
 
         # Allocate locks:
-        self._lock = threading.RLock()
-        self.__commit_lock = threading.Lock()
+        self._lock = utils.RLock()
+        self.__commit_lock = utils.Lock()
 
         # Comment out the following 4 lines to debug locking:
         self._lock_acquire = self._lock.acquire
@@ -108,45 +107,6 @@ def __init__(self, name, base=None):
         else:
             self._oid = oid
 
-    ########################################################################
-    # The following methods are normally overridden on instances,
-    # except when debugging:
-
-    def _lock_acquire(self, *args):
-        f = sys._getframe(1)
-        sys.stdout.write("[la(%s:%s)\n" % (f.f_code.co_filename, f.f_lineno))
-        sys.stdout.flush()
-        self._lock.acquire(*args)
-        sys.stdout.write("la(%s:%s)]\n" % (f.f_code.co_filename, f.f_lineno))
-        sys.stdout.flush()
-
-    def _lock_release(self, *args):
-        f = sys._getframe(1)
-        sys.stdout.write("[lr(%s:%s)\n" % (f.f_code.co_filename, f.f_lineno))
-        sys.stdout.flush()
-        self._lock.release(*args)
-        sys.stdout.write("lr(%s:%s)]\n" % (f.f_code.co_filename, f.f_lineno))
-        sys.stdout.flush()
-
-    def _commit_lock_acquire(self, *args):
-        f = sys._getframe(1)
-        sys.stdout.write("[ca(%s:%s)\n" % (f.f_code.co_filename, f.f_lineno))
-        sys.stdout.flush()
-        self.__commit_lock.acquire(*args)
-        sys.stdout.write("ca(%s:%s)]\n" % (f.f_code.co_filename, f.f_lineno))
-        sys.stdout.flush()
-
-    def _commit_lock_release(self, *args):
-        f = sys._getframe(1)
-        sys.stdout.write("[cr(%s:%s)\n" % (f.f_code.co_filename, f.f_lineno))
-        sys.stdout.flush()
-        self.__commit_lock.release(*args)
-        sys.stdout.write("cr(%s:%s)]\n" % (f.f_code.co_filename, f.f_lineno))
-        sys.stdout.flush()
-
-    #
-    ########################################################################
-
     def sortKey(self):
         """Return a string that can be used to sort storage instances.