From: Mike Bayer Date: Wed, 7 Oct 2020 12:42:48 +0000 (-0400) Subject: Use monotonic time for pool age measurement X-Git-Tag: rel_1_4_0b1~50 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=0220b58917b5a979891b5765f6ac5095e0368489;p=thirdparty%2Fsqlalchemy%2Fsqlalchemy.git Use monotonic time for pool age measurement The internal clock used by the :class:`_pool.Pool` object is now time.monotonic_time() under Python 3. Under Python 2, time.time() is still used, which is legacy. This clock is used to measure the age of a connection against its starttime, and used in comparisons against the pool_timeout setting as well as the last time the pool was marked as invalid to determine if the connection should be recycled. Previously, time.time() was used which was subject to inaccuracies as a result of system clock changes as well as poor time resolution on windows. Change-Id: I94f90044c1809508e26a5a00134981c2a00d0405 --- diff --git a/doc/build/changelog/unreleased_14/monotonic_time.rst b/doc/build/changelog/unreleased_14/monotonic_time.rst new file mode 100644 index 0000000000..dc733d8a9e --- /dev/null +++ b/doc/build/changelog/unreleased_14/monotonic_time.rst @@ -0,0 +1,11 @@ +.. change:: + :tags: change, bug + + The internal clock used by the :class:`_pool.Pool` object is now + time.monotonic_time() under Python 3. Under Python 2, time.time() is still + used, which is legacy. This clock is used to measure the age of a + connection against its starttime, and used in comparisons against the + pool_timeout setting as well as the last time the pool was marked as + invalid to determine if the connection should be recycled. Previously, + time.time() was used which was subject to inaccuracies as a result of + system clock changes as well as poor time resolution on windows. diff --git a/lib/sqlalchemy/pool/base.py b/lib/sqlalchemy/pool/base.py index 87383fef71..2f1959f7c8 100644 --- a/lib/sqlalchemy/pool/base.py +++ b/lib/sqlalchemy/pool/base.py @@ -11,16 +11,15 @@ """ from collections import deque -import time import weakref from .. import event from .. import exc from .. import log from .. import util +from ..util import monotonic_time from ..util import threading - reset_rollback = util.symbol("reset_rollback") reset_commit = util.symbol("reset_commit") reset_none = util.symbol("reset_none") @@ -261,7 +260,7 @@ class Pool(log.Identified): """ rec = getattr(connection, "_connection_record", None) if not rec or self._invalidate_time < rec.starttime: - self._invalidate_time = time.time() + self._invalidate_time = monotonic_time() if _checkin and getattr(connection, "is_valid", False): connection.invalidate(exception) @@ -510,7 +509,7 @@ class _ConnectionRecord(object): self.connection, ) if soft: - self._soft_invalidate_time = time.time() + self._soft_invalidate_time = monotonic_time() else: self.__close() self.connection = None @@ -519,23 +518,16 @@ class _ConnectionRecord(object): recycle = False # NOTE: the various comparisons here are assuming that measurable time - # passes between these state changes. however, time.time() is not - # guaranteed to have sub-second precision. comparisons of - # "invalidation time" to "starttime" should perhaps use >= so that the - # state change can take place assuming no measurable time has passed, - # however this does not guarantee correct behavior here as if time - # continues to not pass, it will try to reconnect repeatedly until - # these timestamps diverge, so in that sense using > is safer. Per - # https://stackoverflow.com/a/1938096/34549, Windows time.time() may be - # within 16 milliseconds accuracy, so unit tests for connection - # invalidation need a sleep of at least this long between initial start - # time and invalidation for the logic below to work reliably. + # passes between these state changes. on Python 2, we are still using + # time.time() which is not guaranteed to have millisecondsecond + # precision, i.e. on Windows. For Python 3 we now use monotonic_time(). + if self.connection is None: self.info.clear() self.__connect() elif ( self.__pool._recycle > -1 - and time.time() - self.starttime > self.__pool._recycle + and monotonic_time() - self.starttime > self.__pool._recycle ): self.__pool.logger.info( "Connection %r exceeded timeout; recycling", self.connection @@ -577,7 +569,7 @@ class _ConnectionRecord(object): # creator fails, this attribute stays None self.connection = None try: - self.starttime = time.time() + self.starttime = monotonic_time() connection = pool._invoke_creator(self) pool.logger.debug("Created new connection %r", connection) self.connection = connection diff --git a/lib/sqlalchemy/testing/requirements.py b/lib/sqlalchemy/testing/requirements.py index 45a2fdf317..e2c61a05ea 100644 --- a/lib/sqlalchemy/testing/requirements.py +++ b/lib/sqlalchemy/testing/requirements.py @@ -15,7 +15,6 @@ to provide specific inclusion/exclusions. """ -import platform import sys from . import exclusions @@ -1093,10 +1092,21 @@ class SuiteRequirements(Requirements): def _running_on_windows(self): return exclusions.LambdaPredicate( - lambda: platform.system() == "Windows", + lambda: util.win32, description="running on Windows", ) + @property + def millisecond_monotonic_time(self): + """the util.monotonic_time() function must be millisecond accurate. + + Under Python 2 we can't guarantee this on Windows. + + """ + return exclusions.skip_if( + lambda: util.win32 and sys.version_info < (3,) + ) + @property def timing_intensive(self): return exclusions.requires_tag("timing_intensive") diff --git a/lib/sqlalchemy/util/__init__.py b/lib/sqlalchemy/util/__init__.py index 8ef2f01032..c0b328d5e9 100644 --- a/lib/sqlalchemy/util/__init__.py +++ b/lib/sqlalchemy/util/__init__.py @@ -64,6 +64,7 @@ from .compat import int_types # noqa from .compat import iterbytes # noqa from .compat import itertools_filter # noqa from .compat import itertools_filterfalse # noqa +from .compat import monotonic_time # noqa from .compat import namedtuple # noqa from .compat import next # noqa from .compat import osx # noqa diff --git a/lib/sqlalchemy/util/compat.py b/lib/sqlalchemy/util/compat.py index d3fefa5265..b94ea353e2 100644 --- a/lib/sqlalchemy/util/compat.py +++ b/lib/sqlalchemy/util/compat.py @@ -109,6 +109,8 @@ if py3k: from io import StringIO from itertools import zip_longest from time import perf_counter + from time import monotonic as monotonic_time + from urllib.parse import ( quote_plus, unquote_plus, @@ -207,6 +209,7 @@ else: from cStringIO import StringIO as byte_buffer # noqa from itertools import izip_longest as zip_longest # noqa from time import clock as perf_counter # noqa + from time import time as monotonic_time # noqa from urllib import quote # noqa from urllib import quote_plus # noqa from urllib import unquote # noqa diff --git a/test/engine/test_pool.py b/test/engine/test_pool.py index eb705da61a..e01609b175 100644 --- a/test/engine/test_pool.py +++ b/test/engine/test_pool.py @@ -1241,7 +1241,7 @@ class QueuePoolTest(PoolTestBase): ) def test_recycle(self): - with patch("sqlalchemy.pool.base.time.time") as mock: + with patch("sqlalchemy.pool.base.monotonic_time") as mock: mock.return_value = 10000 p = self._queuepool_fixture( diff --git a/test/engine/test_reconnect.py b/test/engine/test_reconnect.py index 0ec8fd0bfa..a6cec2ea2f 100644 --- a/test/engine/test_reconnect.py +++ b/test/engine/test_reconnect.py @@ -357,6 +357,8 @@ class PrePingMockTest(fixtures.TestBase): class MockReconnectTest(fixtures.TestBase): + __requires__ = ("millisecond_monotonic_time",) + def setup(self): self.dbapi = MockDBAPI() @@ -402,6 +404,9 @@ class MockReconnectTest(fixtures.TestBase): # set it to fail self.dbapi.shutdown() + + # close on DBAPI connection occurs here, as it is detected + # as invalid. assert_raises(tsa.exc.DBAPIError, conn.execute, select(1)) # assert was invalidated @@ -419,8 +424,14 @@ class MockReconnectTest(fixtures.TestBase): [[call()], []], ) + # checkout makes use of the same connection record. in + # get_connection(), recycle should be enabled because + # the age of the connection is older than the time at which + # the invalidation occurred. conn = self.db.connect() + # therefore the two connections should both have been closed + # when we connected again. eq_( [c.close.mock_calls for c in self.dbapi.connections], [[call()], [call()], []],