Merge pull request #222 from zopefoundation/feature/faster-tests

Avoid most calls to time.sleep() in the tests by mocking time.[gm]time

.travis.yml

@@ -23,8 +23,8 @@ install:
     - pip install -U setuptools zc.buildout
     - buildout $BUILOUT_OPTIONS
 script:
-    - if [[ $TRAVIS_PYTHON_VERSION != pypy* ]]; then bin/coverage run bin/coverage-test -v1j99; fi
-    - if [[ $TRAVIS_PYTHON_VERSION == pypy* ]]; then bin/test -v1j99; fi
+    - if [[ $TRAVIS_PYTHON_VERSION != pypy* ]]; then bin/coverage run bin/coverage-test -v; fi
+    - if [[ $TRAVIS_PYTHON_VERSION == pypy* ]]; then bin/test -v; fi
     - if [[ $TRAVIS_PYTHON_VERSION != pypy3* ]]; then make -C doc html; fi
     - if [[ $TRAVIS_PYTHON_VERSION != pypy* ]]; then pip install coveralls; fi # install early enough to get into the cache
 after_success:

CHANGES.rst

@@ -22,6 +22,8 @@
   exceptions on certain types of bad input. See `issue 216
   <https://github.com/zopefoundation/ZODB/issues/216>`_.
 
+- Make the tests run faster by avoiding calls to ``time.sleep()``.
+
 5.4.0 (2018-03-26)
 ==================
 

appveyor.yml

@@ -14,9 +14,10 @@ environment:
 install:
   - "SET PATH=C:\\Python%PYTHON%;c:\\Python%PYTHON%\\scripts;%PATH%"
   - echo "C:\Program Files\Microsoft SDKs\Windows\v7.1\Bin\SetEnv.cmd" /x64 > "C:\Program Files (x86)\Microsoft Visual Studio 10.0\VC\bin\amd64\vcvars64.bat"
-  - pip install -e .
-  - pip install zope.testrunner zope.testing manuel
-  - pip install zc.buildout zc.recipe.testrunner zc.recipe.egg
+  - python -m pip install -U pip setuptools wheel
+  - pip install -U -e .
+  - pip install -U zope.testrunner zope.testing manuel
+  - pip install -U zc.buildout zc.recipe.testrunner zc.recipe.egg
 
 build_script:
   - buildout bootstrap

setup.py

@@ -43,6 +43,7 @@ long_description = read("README.rst") + "\n\n" + read("CHANGES.rst")
 
 tests_require = [
     'manuel',
+    'mock; python_version == "2.7"',
     'zope.testing',
     'zope.testrunner >= 4.4.6',
 ]

src/ZODB/scripts/tests/test_repozo.py

@@ -19,11 +19,11 @@ from hashlib import md5
 
 import ZODB.tests.util  # layer used at class scope
 
-try:
-    from StringIO import StringIO
-    BytesIO = StringIO
-except ImportError:
-    from io import BytesIO, StringIO
+from io import BytesIO, StringIO
+if str is bytes:
+    NativeStringIO = BytesIO
+else:
+    NativeStringIO = StringIO
 
 
 _NOISY = os.environ.get('NOISY_REPOZO_TEST_OUTPUT')
@@ -94,19 +94,12 @@ class OurDB(object):
 
 class Test_parseargs(unittest.TestCase):
 
-    # Python 2.6 lacks this
-    def assertIn(self, member, container, msg=None):
-        if member not in container:
-            standardMsg = '%s not found in %s' % (repr(member),
-                                                  repr(container))
-            self.fail(self._formatMessage(msg, standardMsg))
-
     def setUp(self):
         from ZODB.scripts import repozo
         self._old_verbosity = repozo.VERBOSE
         self._old_stderr = sys.stderr
         repozo.VERBOSE = False
-        sys.stderr = StringIO()
+        sys.stderr = NativeStringIO()
 
     def tearDown(self):
         from ZODB.scripts import repozo
@@ -134,7 +127,7 @@ class Test_parseargs(unittest.TestCase):
         # zope.testrunner will happily print the traceback and failure message
         # into our StringIO before running our tearDown.
         old_stdout = sys.stdout
-        sys.stdout = StringIO()
+        sys.stdout = NativeStringIO()
         try:
             self.assertRaises(SystemExit, repozo.parseargs, ['--help'])
             self.assertIn('Usage:', sys.stdout.getvalue())
@@ -1099,6 +1092,7 @@ class MonteCarloTests(unittest.TestCase):
         from ZODB.scripts.repozo import main
         main(argv)
 
+    @ZODB.tests.util.time_monotonically_increases
     def test_via_monte_carlo(self):
         self.saved_snapshots = []  # list of (name, time) pairs for copies.
 
@@ -1142,8 +1136,7 @@ class MonteCarloTests(unittest.TestCase):
             copyfile(srcname, copyname)
             self.saved_snapshots.append((copyname, copytime))
 
-        # Make sure the clock moves at least a second.
-        sleep(1.01)
+        # The clock moves forward automatically on calls to time.time()
 
         # Verify current Data.fs can be reproduced exactly.
         self.assertRestored()

src/ZODB/tests/PackableStorage.py

@@ -30,6 +30,7 @@ from ZODB._compat import (loads, PersistentPickler, Pickler, Unpickler,
 import transaction
 import ZODB.interfaces
 import ZODB.tests.util
+from ZODB.tests.util import time_monotonically_increases
 import zope.testing.setupstack
 
 from ZODB.utils import load_current
@@ -274,12 +275,15 @@ class PackableStorage(PackableStorageBase):
 
         db.close()
 
+    @time_monotonically_increases
     def checkPackWhileWriting(self):
         self._PackWhileWriting(pack_now=False)
 
+    @time_monotonically_increases
     def checkPackNowWhileWriting(self):
         self._PackWhileWriting(pack_now=True)
 
+    @time_monotonically_increases
     def checkPackLotsWhileWriting(self):
         # This is like the other pack-while-writing tests, except it packs
         # repeatedly until the client thread is done.  At the time it was
@@ -608,6 +612,7 @@ class PackableUndoStorage(PackableStorageBase):
 
         eq(root['obj'].value, 7)
 
+    @time_monotonically_increases
     def checkRedundantPack(self):
         # It is an error to perform a pack with a packtime earlier
         # than a previous packtime.  The storage can't do a full
@@ -652,6 +657,7 @@ class PackableUndoStorage(PackableStorageBase):
         # it is reachable.
         load_current(self._storage, lost_oid)
 
+    @time_monotonically_increases(0.1)
     def checkPackUndoLog(self):
         self._initroot()
         # Create a `persistent' object
@@ -669,7 +675,7 @@ class PackableUndoStorage(PackableStorageBase):
         self.assertEqual(3, len(self._storage.undoLog()))
         self._storage.pack(packtime, referencesf)
         # The undo log contains only the most resent transaction
-        self.assertEqual(1,len(self._storage.undoLog()))
+        self.assertEqual(1, len(self._storage.undoLog()))
 
     def dont_checkPackUndoLogUndoable(self):
         # A disabled test. I wanted to test that the content of the

src/ZODB/tests/RecoveryStorage.py

@@ -21,6 +21,7 @@ from ZODB import DB
 from ZODB.serialize import referencesf
 
 from ZODB.utils import load_current
+from ZODB.tests.util import time_monotonically_increases
 
 import time
 
@@ -66,6 +67,7 @@ class RecoveryStorage(IteratorDeepCompare):
         self._dst.tpc_vote(final)
         self._dst.tpc_finish(final)
 
+    @time_monotonically_increases
     def checkPackWithGCOnDestinationAfterRestore(self):
         raises = self.assertRaises
         db = DB(self._storage)

src/ZODB/tests/RevisionStorage.py

@@ -17,6 +17,7 @@ from ZODB.Connection import TransactionMetaData
 from ZODB.tests.MinPO import MinPO
 from ZODB.tests.StorageTestBase import zodb_unpickle, zodb_pickle, snooze
 from ZODB.utils import p64, u64, load_current
+from ZODB.tests.util import time_monotonically_increases
 
 ZERO = '\0'*8
 
@@ -34,6 +35,7 @@ class RevisionStorage(object):
             data = self._storage.loadSerial(oid, revid)
             self.assertEqual(zodb_unpickle(data), value)
 
+    @time_monotonically_increases
     def checkLoadBefore(self):
         # Store 10 revisions of one object and then make sure that we
         # can get all the non-current revisions back.
@@ -89,6 +91,7 @@ class RevisionStorage(object):
         self.assertEqual(start, revid1)
         self.assertEqual(end, revid2)
 
+    @time_monotonically_increases
     def checkLoadBeforeOld(self):
         # Look for a very old revision.  With the BaseStorage implementation
         # this should require multple history() calls.

src/ZODB/tests/testCache.py

@@ -378,7 +378,12 @@ class CacheErrors(unittest.TestCase):
             # structure that adds a new reference to None for each executed
             # line of code, which interferes with this test.  So check it
             # only if we're running without coverage tracing.
-            self.assertEqual(rc(None), nones)
+
+            # On Python 3.7, we can see the value of reference counts
+            # to None actually go *down* by a few. Possibly it has to
+            # do with the lazy tracking of frames?
+            # (https://github.com/python/cpython/commit/5a625d0aa6a6d9ec6574ee8344b41d63dcb9897e)
+            self.assertLessEqual(rc(None), nones)
 
     def testTwoCaches(self):
         jar2 = StubDataManager()

src/ZODB/tests/testblob.py

@@ -18,11 +18,7 @@ from ZODB.FileStorage import FileStorage
 from ZODB.tests.testConfig import ConfigTestBase
 from ZODB._compat import Pickler, Unpickler, _protocol
 
-import os
-if os.environ.get('USE_ZOPE_TESTING_DOCTEST'):
-    from zope.testing import doctest
-else:
-    import doctest
+import doctest
 
 import os
 import random
@@ -40,12 +36,7 @@ import ZODB.tests.StorageTestBase
 import ZODB.tests.util
 import zope.testing.renormalizing
 
-
-try:
-    from StringIO import StringIO as BytesIO
-except ImportError:
-    # Py3
-    from io import BytesIO
+from io import BytesIO
 
 try:
     file_type = file
@@ -67,7 +58,11 @@ def new_time():
     now = new_time = time.time()
     while new_time <= now:
         new_time = time.time()
-    time.sleep(1)
+    if time.time() - new_time < 1.0:
+        # Detect if we're in a time monotonically increasing
+        # layer (two back-to-back calls of time.time() advance the clock
+        # by a whole second); if so, we don't need to sleep
+        time.sleep(1.0)
     return new_time
 
 
@@ -703,6 +698,14 @@ def setUp(test):
     ZODB.tests.util.setUp(test)
     test.globs['rmtree'] = zope.testing.setupstack.rmtree
 
+def timeIncreasesSetUp(test):
+    setUp(test)
+    l = test.globs['time_layer'] = ZODB.tests.util.MonotonicallyIncreasingTimeMinimalTestLayer('')
+    l.testSetUp()
+
+def timeIncreasesTearDown(test):
+    test.globs['time_layer'].testTearDown()
+    util.tearDown(test)
 
 def setUpBlobAdaptedFileStorage(test):
     setUp(test)
@@ -791,7 +794,7 @@ def storage_reusable_suite(prefix, factory,
     if test_undo:
         add_test_based_on_test_class(BlobUndoTests)
 
-    suite.layer = ZODB.tests.util.MininalTestLayer(prefix+'BlobTests')
+    suite.layer = ZODB.tests.util.MonotonicallyIncreasingTimeMinimalTestLayer(prefix+'BlobTests')
 
     return suite
 
@@ -804,12 +807,18 @@ def test_suite():
         "blob_basic.txt",
         "blob_consume.txt",
         "blob_tempdir.txt",
-        "blobstorage_packing.txt",
         setUp=setUp,
         tearDown=util.tearDown,
         optionflags=doctest.ELLIPSIS,
         checker=ZODB.tests.util.checker,
         ))
+    suite.addTest(doctest.DocFileSuite(
+        "blobstorage_packing.txt",
+        setUp=timeIncreasesSetUp,
+        tearDown=timeIncreasesTearDown,
+        optionflags=doctest.ELLIPSIS,
+        checker=ZODB.tests.util.checker,
+        ))
     suite.addTest(doctest.DocFileSuite(
         "blob_layout.txt",
         optionflags=doctest.ELLIPSIS|doctest.NORMALIZE_WHITESPACE,

src/ZODB/tests/util.py

@@ -29,6 +29,19 @@ from ZODB.Connection import TransactionMetaData
 import zope.testing.setupstack
 from zope.testing import renormalizing
 
+try:
+    from unittest import mock
+except ImportError:
+    import mock
+
+import six
+import functools
+from time import time as _real_time
+from time import gmtime as _real_gmtime
+_current_time = _real_time()
+
+
+
 checker = renormalizing.RENormalizing([
     (re.compile("<(.*?) object at 0x[0-9a-f]*?>"),
      r"<\1 object at 0x000000000000>"),
@@ -206,3 +219,122 @@ def clear_transaction_syncs():
     for this.
     """
     transaction.manager.clearSynchs()
+
+
+class _TimeWrapper(object):
+
+    def __init__(self, granularity=1.0):
+        self._granularity = granularity
+        self._lock = ZODB.utils.Lock()
+        self.fake_gmtime = mock.Mock()
+        self.fake_time = mock.Mock()
+        self._configure_fakes()
+
+    def _configure_fakes(self):
+        def incr():
+            global _current_time # pylint:disable=global-statement
+            with self._lock:
+                _current_time = max(_real_time(), _current_time + self._granularity)
+            return _current_time
+        self.fake_time.side_effect = incr
+
+        def incr_gmtime(seconds=None):
+            if seconds is not None:
+                now = seconds
+            else:
+                now = incr()
+            return _real_gmtime(now)
+        self.fake_gmtime.side_effect = incr_gmtime
+
+    def install_fakes(self):
+        time.time = self.fake_time
+        time.gmtime = self.fake_gmtime
+
+    __enter__ = install_fakes
+
+    def close(self, *args):
+        time.time = _real_time
+        time.gmtime = _real_gmtime
+
+    __exit__ = close
+
+    def __call__(self, func):
+        @functools.wraps(func)
+        def wrapper(*args, **kwargs):
+            with self:
+                return func(*args, **kwargs)
+        return wrapper
+
+
+def time_monotonically_increases(func_or_granularity):
+    """
+    Decorate a unittest method with this function to cause the value
+    of :func:`time.time` and :func:`time.gmtime` to monotonically
+    increase by one each time it is called. This ensures things like
+    last modified dates always increase.
+
+    We make three guarantees about the value of :func:`time.time`
+    returned while the decorated function is running:
+
+        1. It is always *at least* the value of the *real*
+           :func:`time.time`;
+
+        2. Each call returns a value greater than the previous call;
+
+        3. Those two constraints hold across different invocations of
+           functions decorated. This decorator can be applied to a
+           method in a test case::
+
+               class TestThing(unittest.TestCase)
+                   @time_monotonically_increases
+                   def test_method(self):
+                     t = time.time()
+                      ...
+
+    It can also be applied to a bare function taking any number of
+    arguments::
+
+        @time_monotonically_increases
+        def utility_function(a, b, c=1):
+           t = time.time()
+           ...
+
+    By default, the time will be incremented in 1.0 second intervals.
+    You can specify a particular granularity as an argument; this is
+    useful to keep from running too far ahead of the real clock::
+
+        @time_monotonically_increases(0.1)
+        def smaller_increment():
+            t1 = time.time()
+            t2 = time.time()
+            assrt t2 == t1 + 0.1
+    """
+    if isinstance(func_or_granularity, (six.integer_types, float)):
+        # We're being used as a factory.
+        wrapper_factory = _TimeWrapper(func_or_granularity)
+        return wrapper_factory
+
+    # We're being used bare
+    wrapper_factory = _TimeWrapper()
+    return wrapper_factory(func_or_granularity)
+
+
+def reset_monotonic_time(value=0.0):
+    """
+    Make the monotonic clock return the real time on its next
+    call.
+    """
+
+    global _current_time # pylint:disable=global-statement
+    _current_time = value
+
+
+class MonotonicallyIncreasingTimeMinimalTestLayer(MininalTestLayer):
+
+    def testSetUp(self):
+        self.time_manager = _TimeWrapper()
+        self.time_manager.install_fakes()
+
+    def testTearDown(self):
+        self.time_manager.close()
+        reset_monotonic_time()

tox.ini

@@ -13,10 +13,7 @@ envlist = py27,py34,py35,py36,py37,pypy,pypy3
 # out of the tox site-packages.
 usedevelop = true
 commands =
-# Run unit tests first.
-    zope-testrunner -u --test-path=src []
-# Only run functional tests if unit tests pass.
-    zope-testrunner -f -j5 --test-path=src []
+    zope-testrunner --test-path=src []
 deps =
     .[test]