Commit e0bc8bd5 authored by Jason Madden's avatar Jason Madden

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

This also makes us more deterministic. (Based on code I wrote for nti.testing.)

On my machine, this speeds up a sequential test run from 4:08 to 1:30.

We no longer get much benefit from running the layer tests in
parallel, in fact it looks like the overhead actually slows them down
slightly, so stop doing that.
parent b8308c6e
...@@ -23,8 +23,8 @@ install: ...@@ -23,8 +23,8 @@ install:
- pip install -U setuptools zc.buildout - pip install -U setuptools zc.buildout
- buildout $BUILOUT_OPTIONS - buildout $BUILOUT_OPTIONS
script: script:
- if [[ $TRAVIS_PYTHON_VERSION != pypy* ]]; then bin/coverage run bin/coverage-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 -v1j99; 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 != 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 - if [[ $TRAVIS_PYTHON_VERSION != pypy* ]]; then pip install coveralls; fi # install early enough to get into the cache
after_success: after_success:
......
...@@ -22,6 +22,8 @@ ...@@ -22,6 +22,8 @@
exceptions on certain types of bad input. See `issue 216 exceptions on certain types of bad input. See `issue 216
<https://github.com/zopefoundation/ZODB/issues/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) 5.4.0 (2018-03-26)
================== ==================
......
...@@ -14,9 +14,10 @@ environment: ...@@ -14,9 +14,10 @@ environment:
install: install:
- "SET PATH=C:\\Python%PYTHON%;c:\\Python%PYTHON%\\scripts;%PATH%" - "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" - 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 . - python -m pip install -U pip setuptools wheel
- pip install zope.testrunner zope.testing manuel - pip install -U -e .
- pip install zc.buildout zc.recipe.testrunner zc.recipe.egg - pip install -U zope.testrunner zope.testing manuel
- pip install -U zc.buildout zc.recipe.testrunner zc.recipe.egg
build_script: build_script:
- buildout bootstrap - buildout bootstrap
......
...@@ -43,6 +43,7 @@ long_description = read("README.rst") + "\n\n" + read("CHANGES.rst") ...@@ -43,6 +43,7 @@ long_description = read("README.rst") + "\n\n" + read("CHANGES.rst")
tests_require = [ tests_require = [
'manuel', 'manuel',
'mock; python_version == "2.7"',
'zope.testing', 'zope.testing',
'zope.testrunner >= 4.4.6', 'zope.testrunner >= 4.4.6',
] ]
......
...@@ -19,11 +19,11 @@ from hashlib import md5 ...@@ -19,11 +19,11 @@ from hashlib import md5
import ZODB.tests.util # layer used at class scope import ZODB.tests.util # layer used at class scope
try: from io import BytesIO, StringIO
from StringIO import StringIO if str is bytes:
BytesIO = StringIO NativeStringIO = BytesIO
except ImportError: else:
from io import BytesIO, StringIO NativeStringIO = StringIO
_NOISY = os.environ.get('NOISY_REPOZO_TEST_OUTPUT') _NOISY = os.environ.get('NOISY_REPOZO_TEST_OUTPUT')
...@@ -94,19 +94,12 @@ class OurDB(object): ...@@ -94,19 +94,12 @@ class OurDB(object):
class Test_parseargs(unittest.TestCase): 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): def setUp(self):
from ZODB.scripts import repozo from ZODB.scripts import repozo
self._old_verbosity = repozo.VERBOSE self._old_verbosity = repozo.VERBOSE
self._old_stderr = sys.stderr self._old_stderr = sys.stderr
repozo.VERBOSE = False repozo.VERBOSE = False
sys.stderr = StringIO() sys.stderr = NativeStringIO()
def tearDown(self): def tearDown(self):
from ZODB.scripts import repozo from ZODB.scripts import repozo
...@@ -134,7 +127,7 @@ class Test_parseargs(unittest.TestCase): ...@@ -134,7 +127,7 @@ class Test_parseargs(unittest.TestCase):
# zope.testrunner will happily print the traceback and failure message # zope.testrunner will happily print the traceback and failure message
# into our StringIO before running our tearDown. # into our StringIO before running our tearDown.
old_stdout = sys.stdout old_stdout = sys.stdout
sys.stdout = StringIO() sys.stdout = NativeStringIO()
try: try:
self.assertRaises(SystemExit, repozo.parseargs, ['--help']) self.assertRaises(SystemExit, repozo.parseargs, ['--help'])
self.assertIn('Usage:', sys.stdout.getvalue()) self.assertIn('Usage:', sys.stdout.getvalue())
...@@ -1099,6 +1092,7 @@ class MonteCarloTests(unittest.TestCase): ...@@ -1099,6 +1092,7 @@ class MonteCarloTests(unittest.TestCase):
from ZODB.scripts.repozo import main from ZODB.scripts.repozo import main
main(argv) main(argv)
@ZODB.tests.util.time_monotonically_increases
def test_via_monte_carlo(self): def test_via_monte_carlo(self):
self.saved_snapshots = [] # list of (name, time) pairs for copies. self.saved_snapshots = [] # list of (name, time) pairs for copies.
...@@ -1142,8 +1136,7 @@ class MonteCarloTests(unittest.TestCase): ...@@ -1142,8 +1136,7 @@ class MonteCarloTests(unittest.TestCase):
copyfile(srcname, copyname) copyfile(srcname, copyname)
self.saved_snapshots.append((copyname, copytime)) self.saved_snapshots.append((copyname, copytime))
# Make sure the clock moves at least a second. # The clock moves forward automatically on calls to time.time()
sleep(1.01)
# Verify current Data.fs can be reproduced exactly. # Verify current Data.fs can be reproduced exactly.
self.assertRestored() self.assertRestored()
......
...@@ -30,6 +30,7 @@ from ZODB._compat import (loads, PersistentPickler, Pickler, Unpickler, ...@@ -30,6 +30,7 @@ from ZODB._compat import (loads, PersistentPickler, Pickler, Unpickler,
import transaction import transaction
import ZODB.interfaces import ZODB.interfaces
import ZODB.tests.util import ZODB.tests.util
from ZODB.tests.util import time_monotonically_increases
import zope.testing.setupstack import zope.testing.setupstack
from ZODB.utils import load_current from ZODB.utils import load_current
...@@ -274,12 +275,15 @@ class PackableStorage(PackableStorageBase): ...@@ -274,12 +275,15 @@ class PackableStorage(PackableStorageBase):
db.close() db.close()
@time_monotonically_increases
def checkPackWhileWriting(self): def checkPackWhileWriting(self):
self._PackWhileWriting(pack_now=False) self._PackWhileWriting(pack_now=False)
@time_monotonically_increases
def checkPackNowWhileWriting(self): def checkPackNowWhileWriting(self):
self._PackWhileWriting(pack_now=True) self._PackWhileWriting(pack_now=True)
@time_monotonically_increases
def checkPackLotsWhileWriting(self): def checkPackLotsWhileWriting(self):
# This is like the other pack-while-writing tests, except it packs # This is like the other pack-while-writing tests, except it packs
# repeatedly until the client thread is done. At the time it was # repeatedly until the client thread is done. At the time it was
...@@ -608,6 +612,7 @@ class PackableUndoStorage(PackableStorageBase): ...@@ -608,6 +612,7 @@ class PackableUndoStorage(PackableStorageBase):
eq(root['obj'].value, 7) eq(root['obj'].value, 7)
@time_monotonically_increases
def checkRedundantPack(self): def checkRedundantPack(self):
# It is an error to perform a pack with a packtime earlier # It is an error to perform a pack with a packtime earlier
# than a previous packtime. The storage can't do a full # than a previous packtime. The storage can't do a full
...@@ -652,6 +657,7 @@ class PackableUndoStorage(PackableStorageBase): ...@@ -652,6 +657,7 @@ class PackableUndoStorage(PackableStorageBase):
# it is reachable. # it is reachable.
load_current(self._storage, lost_oid) load_current(self._storage, lost_oid)
@time_monotonically_increases(0.1)
def checkPackUndoLog(self): def checkPackUndoLog(self):
self._initroot() self._initroot()
# Create a `persistent' object # Create a `persistent' object
...@@ -669,7 +675,7 @@ class PackableUndoStorage(PackableStorageBase): ...@@ -669,7 +675,7 @@ class PackableUndoStorage(PackableStorageBase):
self.assertEqual(3, len(self._storage.undoLog())) self.assertEqual(3, len(self._storage.undoLog()))
self._storage.pack(packtime, referencesf) self._storage.pack(packtime, referencesf)
# The undo log contains only the most resent transaction # 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): def dont_checkPackUndoLogUndoable(self):
# A disabled test. I wanted to test that the content of the # A disabled test. I wanted to test that the content of the
......
...@@ -21,6 +21,7 @@ from ZODB import DB ...@@ -21,6 +21,7 @@ from ZODB import DB
from ZODB.serialize import referencesf from ZODB.serialize import referencesf
from ZODB.utils import load_current from ZODB.utils import load_current
from ZODB.tests.util import time_monotonically_increases
import time import time
...@@ -66,6 +67,7 @@ class RecoveryStorage(IteratorDeepCompare): ...@@ -66,6 +67,7 @@ class RecoveryStorage(IteratorDeepCompare):
self._dst.tpc_vote(final) self._dst.tpc_vote(final)
self._dst.tpc_finish(final) self._dst.tpc_finish(final)
@time_monotonically_increases
def checkPackWithGCOnDestinationAfterRestore(self): def checkPackWithGCOnDestinationAfterRestore(self):
raises = self.assertRaises raises = self.assertRaises
db = DB(self._storage) db = DB(self._storage)
......
...@@ -17,6 +17,7 @@ from ZODB.Connection import TransactionMetaData ...@@ -17,6 +17,7 @@ from ZODB.Connection import TransactionMetaData
from ZODB.tests.MinPO import MinPO from ZODB.tests.MinPO import MinPO
from ZODB.tests.StorageTestBase import zodb_unpickle, zodb_pickle, snooze from ZODB.tests.StorageTestBase import zodb_unpickle, zodb_pickle, snooze
from ZODB.utils import p64, u64, load_current from ZODB.utils import p64, u64, load_current
from ZODB.tests.util import time_monotonically_increases
ZERO = '\0'*8 ZERO = '\0'*8
...@@ -34,6 +35,7 @@ class RevisionStorage(object): ...@@ -34,6 +35,7 @@ class RevisionStorage(object):
data = self._storage.loadSerial(oid, revid) data = self._storage.loadSerial(oid, revid)
self.assertEqual(zodb_unpickle(data), value) self.assertEqual(zodb_unpickle(data), value)
@time_monotonically_increases
def checkLoadBefore(self): def checkLoadBefore(self):
# Store 10 revisions of one object and then make sure that we # Store 10 revisions of one object and then make sure that we
# can get all the non-current revisions back. # can get all the non-current revisions back.
...@@ -89,6 +91,7 @@ class RevisionStorage(object): ...@@ -89,6 +91,7 @@ class RevisionStorage(object):
self.assertEqual(start, revid1) self.assertEqual(start, revid1)
self.assertEqual(end, revid2) self.assertEqual(end, revid2)
@time_monotonically_increases
def checkLoadBeforeOld(self): def checkLoadBeforeOld(self):
# Look for a very old revision. With the BaseStorage implementation # Look for a very old revision. With the BaseStorage implementation
# this should require multple history() calls. # this should require multple history() calls.
......
...@@ -18,11 +18,7 @@ from ZODB.FileStorage import FileStorage ...@@ -18,11 +18,7 @@ from ZODB.FileStorage import FileStorage
from ZODB.tests.testConfig import ConfigTestBase from ZODB.tests.testConfig import ConfigTestBase
from ZODB._compat import Pickler, Unpickler, _protocol from ZODB._compat import Pickler, Unpickler, _protocol
import os import doctest
if os.environ.get('USE_ZOPE_TESTING_DOCTEST'):
from zope.testing import doctest
else:
import doctest
import os import os
import random import random
...@@ -40,12 +36,7 @@ import ZODB.tests.StorageTestBase ...@@ -40,12 +36,7 @@ import ZODB.tests.StorageTestBase
import ZODB.tests.util import ZODB.tests.util
import zope.testing.renormalizing import zope.testing.renormalizing
from io import BytesIO
try:
from StringIO import StringIO as BytesIO
except ImportError:
# Py3
from io import BytesIO
try: try:
file_type = file file_type = file
...@@ -67,7 +58,11 @@ def new_time(): ...@@ -67,7 +58,11 @@ def new_time():
now = new_time = time.time() now = new_time = time.time()
while new_time <= now: while new_time <= now:
new_time = time.time() 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 return new_time
...@@ -703,6 +698,14 @@ def setUp(test): ...@@ -703,6 +698,14 @@ def setUp(test):
ZODB.tests.util.setUp(test) ZODB.tests.util.setUp(test)
test.globs['rmtree'] = zope.testing.setupstack.rmtree 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): def setUpBlobAdaptedFileStorage(test):
setUp(test) setUp(test)
...@@ -791,7 +794,7 @@ def storage_reusable_suite(prefix, factory, ...@@ -791,7 +794,7 @@ def storage_reusable_suite(prefix, factory,
if test_undo: if test_undo:
add_test_based_on_test_class(BlobUndoTests) 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 return suite
...@@ -804,12 +807,18 @@ def test_suite(): ...@@ -804,12 +807,18 @@ def test_suite():
"blob_basic.txt", "blob_basic.txt",
"blob_consume.txt", "blob_consume.txt",
"blob_tempdir.txt", "blob_tempdir.txt",
"blobstorage_packing.txt",
setUp=setUp, setUp=setUp,
tearDown=util.tearDown, tearDown=util.tearDown,
optionflags=doctest.ELLIPSIS, optionflags=doctest.ELLIPSIS,
checker=ZODB.tests.util.checker, 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( suite.addTest(doctest.DocFileSuite(
"blob_layout.txt", "blob_layout.txt",
optionflags=doctest.ELLIPSIS|doctest.NORMALIZE_WHITESPACE, optionflags=doctest.ELLIPSIS|doctest.NORMALIZE_WHITESPACE,
......
...@@ -29,6 +29,19 @@ from ZODB.Connection import TransactionMetaData ...@@ -29,6 +29,19 @@ from ZODB.Connection import TransactionMetaData
import zope.testing.setupstack import zope.testing.setupstack
from zope.testing import renormalizing 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([ checker = renormalizing.RENormalizing([
(re.compile("<(.*?) object at 0x[0-9a-f]*?>"), (re.compile("<(.*?) object at 0x[0-9a-f]*?>"),
r"<\1 object at 0x000000000000>"), r"<\1 object at 0x000000000000>"),
...@@ -206,3 +219,122 @@ def clear_transaction_syncs(): ...@@ -206,3 +219,122 @@ def clear_transaction_syncs():
for this. for this.
""" """
transaction.manager.clearSynchs() 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()
...@@ -13,10 +13,7 @@ envlist = py27,py34,py35,py36,py37,pypy,pypy3 ...@@ -13,10 +13,7 @@ envlist = py27,py34,py35,py36,py37,pypy,pypy3
# out of the tox site-packages. # out of the tox site-packages.
usedevelop = true usedevelop = true
commands = commands =
# Run unit tests first. zope-testrunner --test-path=src []
zope-testrunner -u --test-path=src []
# Only run functional tests if unit tests pass.
zope-testrunner -f -j5 --test-path=src []
deps = deps =
.[test] .[test]
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment