]> git.ipfire.org Git - thirdparty/sqlalchemy/sqlalchemy.git/commitdiff
Use monotonic time for pool age measurement
authorMike Bayer <mike_mp@zzzcomputing.com>
Wed, 7 Oct 2020 12:42:48 +0000 (08:42 -0400)
committerMike Bayer <mike_mp@zzzcomputing.com>
Wed, 7 Oct 2020 13:14:13 +0000 (09:14 -0400)
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

doc/build/changelog/unreleased_14/monotonic_time.rst [new file with mode: 0644]
lib/sqlalchemy/pool/base.py
lib/sqlalchemy/testing/requirements.py
lib/sqlalchemy/util/__init__.py
lib/sqlalchemy/util/compat.py
test/engine/test_pool.py
test/engine/test_reconnect.py

diff --git a/doc/build/changelog/unreleased_14/monotonic_time.rst b/doc/build/changelog/unreleased_14/monotonic_time.rst
new file mode 100644 (file)
index 0000000..dc733d8
--- /dev/null
@@ -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.
index 87383fef717a6a1d76b44e4d625d6eb405a9f431..2f1959f7c8bd633667f5b7360533c99cc9d50274 100644 (file)
 """
 
 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
index 45a2fdf3176ca19c9f7449448beb546091370d2a..e2c61a05eadd8d31ab52b13b844af6c95377c5a4 100644 (file)
@@ -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")
index 8ef2f010321879f0cce341cc04c63a6f2171f096..c0b328d5e9e824be9dc84d596bd29f7b47eda5d2 100644 (file)
@@ -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
index d3fefa526578ddc19315c7f100f1fc62d86df245..b94ea353e20e522c4ece250f7d523113bc99309c 100644 (file)
@@ -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
index eb705da61abe88ca3d1eab20506f52f4e9289b95..e01609b17548ac02a2dfc94592df12398d8c7fbc 100644 (file)
@@ -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(
index 0ec8fd0bfaaf56e11de5f6da1e168e91fb53e71e..a6cec2ea2fabe79493c7cf4dc6b3b354255d7790 100644 (file)
@@ -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()], []],