From 9d83ef23f4ec72b55316e58bfd52d2ca858c2cef Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Mon, 8 May 2023 17:16:04 +0530 Subject: [PATCH 01/24] feat: session leak changes --- google/cloud/spanner_v1/database.py | 26 ++++++++- google/cloud/spanner_v1/pool.py | 87 ++++++++++++++++++++++++++--- google/cloud/spanner_v1/session.py | 32 +++++++++++ noxfile.py | 4 +- samples/samples/batchinsert.py | 32 +++++++++++ samples/samples/snippets.py | 27 ++++++++- samples/samples/snippets_test.py | 6 ++ test.py | 56 +++++++++++++++++-- tests/unit/test_database.py | 2 +- tests/unit/test_pool.py | 20 ++++++- 10 files changed, 272 insertions(+), 20 deletions(-) create mode 100644 samples/samples/batchinsert.py diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index f78fff7816..8fc2451f51 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -20,6 +20,7 @@ import logging import re import threading +import logging import google.auth.credentials from google.api_core.retry import Retry @@ -137,7 +138,9 @@ def __init__( instance, ddl_statements=(), pool=None, + logging_enabled=False, logger=None, + close_inactive_transactions=True, encryption_config=None, database_dialect=DatabaseDialect.DATABASE_DIALECT_UNSPECIFIED, database_role=None, @@ -154,7 +157,9 @@ def __init__( self._encryption_info = None self._default_leader = None self.log_commit_stats = False + self._logging_enabled = logging_enabled self._logger = logger + self._close_inactive_transactions = close_inactive_transactions self._encryption_config = encryption_config self._database_dialect = database_dialect self._database_role = database_role @@ -331,12 +336,20 @@ def database_role(self): :returns: a str with the name of the database role. """ return self._database_role + + @property + def logging_enabled(self): + """Test if logging is enabled. Default: False. + :rtype: bool + :returns: True if logging is enabled, else False. + """ + return self._logging_enabled @property def logger(self): """Logger used by the database. - The default logger will log commit stats at the log level INFO using + The default logger will log at the log level INFO using `sys.stderr`. :rtype: :class:`logging.Logger` or `None` @@ -351,6 +364,14 @@ def logger(self): self._logger.addHandler(ch) return self._logger + @property + def close_inactive_transactions(self): + """Test if closing inactive transactions is enabled. Default: True. + :rtype: bool + :returns: True if closing inactive transactions is enabled, else False. + """ + return self._close_inactive_transactions + @property def spanner_api(self): """Helper for session-related API calls.""" @@ -575,7 +596,7 @@ def execute_partitioned_dml( ) def execute_pdml(): - with SessionCheckout(self._pool) as session: + with SessionCheckout(self._pool, isLongRunning=True) as session: txn = api.begin_transaction( session=session.name, options=txn_options, metadata=metadata @@ -966,6 +987,7 @@ def __exit__(self, exc_type, exc_val, exc_tb): "CommitStats: {}".format(self._batch.commit_stats), extra={"commit_stats": self._batch.commit_stats}, ) + logging.debug("Session details {}".format(self._session.checkout_time)) self._database._pool.put(self._session) diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index 56837bfc0b..a77dc8b434 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -16,7 +16,9 @@ import datetime import queue - +import threading +import random +import time from google.cloud.exceptions import NotFound from google.cloud.spanner_v1 import BatchCreateSessionsRequest from google.cloud.spanner_v1 import Session @@ -25,10 +27,10 @@ _metadata_with_leader_aware_routing, ) from warnings import warn +import logging _NOW = datetime.datetime.utcnow # unit tests may replace - class AbstractSessionPool(object): """Specifies required API for concrete session pool implementations. @@ -41,6 +43,11 @@ class AbstractSessionPool(object): """ _database = None + _sessions = None + _borrowed_sessions = [] + + _cleanup_task_ongoing_event = threading.Event() + _cleanup_task_ongoing = False def __init__(self, labels=None, database_role=None): if labels is None: @@ -80,9 +87,12 @@ def bind(self, database): """ raise NotImplementedError() - def get(self): + def get(self, isLongRunning=False): """Check a session out from the pool. + :type isLongRunning: bool + :param isLongRunning: Specifies if the session fetched is for long running transaction or not. + Concrete implementations of this method are allowed to raise an error to signal that the pool is exhausted, or to block until a session is available. @@ -138,6 +148,34 @@ def session(self, **kwargs): """ return SessionCheckout(self, **kwargs) + def startCleaningLongRunningSessions(self): + if not AbstractSessionPool._cleanup_task_ongoing_event.is_set() and not AbstractSessionPool._cleanup_task_ongoing: + AbstractSessionPool._cleanup_task_ongoing_event.set() + background = threading.Thread(target=self.deleteLongRunningTransactions, args=(120,), daemon=True, name='recycle-sessions') + background.start() + + def stopCleaningLongRunningSessions(self): + AbstractSessionPool._cleanup_task_ongoing_event.clear() + + def deleteLongRunningTransactions(self, interval_sec): + while AbstractSessionPool._cleanup_task_ongoing_event.is_set(): + AbstractSessionPool._cleanup_task_ongoing = True + logging.debug("delete long running started") + start = time.time() + sessions_to_delete = (session for session in self._borrowed_sessions + if (datetime.datetime.utcnow() - session.checkout_time > datetime.timedelta(minutes=60)) + and not session.long_running) + for session in sessions_to_delete: + if self._database.logging_enabled: + self._database.logger.warn("Removing long runinng sess") + if self._database.close_inactive_transactions: + self.put(session) + + elapsed_time = time.time() - start + if interval_sec - elapsed_time > 0: + time.sleep(interval_sec - elapsed_time) + logging.debug("setting flag as False") + AbstractSessionPool._cleanup_task_ongoing = False class FixedSizePool(AbstractSessionPool): """Concrete session pool implementation: @@ -183,7 +221,6 @@ def __init__( self.size = size self.default_timeout = default_timeout self._sessions = queue.LifoQueue(size) - def bind(self, database): """Associate the pool with a database. @@ -215,7 +252,7 @@ def bind(self, database): session._session_id = session_pb.name.split("/")[-1] self._sessions.put(session) - def get(self, timeout=None): + def get(self, isLongRunning=False, timeout=None): """Check a session out from the pool. :type timeout: int @@ -235,6 +272,11 @@ def get(self, timeout=None): session = self._database.session() session.create() + session.checkout_time = datetime.datetime.utcnow() + session.long_running = isLongRunning + self._borrowed_sessions.append(session) + if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : + self.startCleaningLongRunningSessions() return session def put(self, session): @@ -247,7 +289,12 @@ def put(self, session): :raises: :exc:`queue.Full` if the queue is full. """ + if self._borrowed_sessions.__contains__(session): + self._borrowed_sessions.remove(session) self._sessions.put_nowait(session) + + if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size < 0.95 : + self.stopCleaningLongRunningSessions() def clear(self): """Delete all sessions in the pool.""" @@ -300,7 +347,7 @@ def bind(self, database): self._database = database self._database_role = self._database_role or self._database.database_role - def get(self): + def get(self, isLongRunning=False): """Check a session out from the pool. :rtype: :class:`~google.cloud.spanner_v1.session.Session` @@ -316,6 +363,13 @@ def get(self): if not session.exists(): session = self._new_session() session.create() + session.checkout_time = datetime.datetime.utcnow() + session.long_running = isLongRunning + self._borrowed_sessions.append(session) + if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.target_size >= 0.55 : + self.startCleaningLongRunningSessions() + if self._database.logging_enabled: + print("log") return session def put(self, session): @@ -328,7 +382,11 @@ def put(self, session): :param session: the session being returned. """ try: + if self._borrowed_sessions.__contains__(session): + self._borrowed_sessions.remove(session) self._sessions.put_nowait(session) + if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.target_size < 0.95 : + self.stopCleaningLongRunningSessions() except queue.Full: try: session.delete() @@ -433,7 +491,7 @@ def bind(self, database): self.put(session) created_session_count += len(resp.session) - def get(self, timeout=None): + def get(self, isLongRunning=False, timeout=None): """Check a session out from the pool. :type timeout: int @@ -457,6 +515,13 @@ def get(self, timeout=None): session = self._new_session() session.create() + session.checkout_time = datetime.datetime.utcnow() + session.long_running = isLongRunning + self._borrowed_sessions.append(session) + if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : + self.startCleaningLongRunningSessions() + if self._database.logging_enabled: + print("log") return session def put(self, session): @@ -469,7 +534,11 @@ def put(self, session): :raises: :exc:`queue.Full` if the queue is full. """ + if self._borrowed_sessions.__contains__(session): + self._borrowed_sessions.remove(session) self._sessions.put_nowait((_NOW() + self._delta, session)) + if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size < 0.95 : + self.stopCleaningLongRunningSessions() def clear(self): """Delete all sessions in the pool.""" @@ -592,7 +661,11 @@ def put(self, session): txn = session._transaction if txn is None or txn.committed or txn.rolled_back: session.transaction() + if self._borrowed_sessions.__contains__(session): + self._borrowed_sessions.remove(session) self._pending_sessions.put(session) + if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size < 0.95 : + self.stopCleaningLongRunningSessions() else: super(TransactionPingingPool, self).put(session) diff --git a/google/cloud/spanner_v1/session.py b/google/cloud/spanner_v1/session.py index 256e72511b..8453df848a 100644 --- a/google/cloud/spanner_v1/session.py +++ b/google/cloud/spanner_v1/session.py @@ -94,6 +94,38 @@ def labels(self): :returns: the labels dict (empty if no labels were assigned. """ return self._labels + + @property + def checkout_time(self): + """Get Check out time for session + :rtype: time + :returns: the checkedout time for a session if assigned. + """ + return self._checkout_time + + @checkout_time.setter + def checkout_time(self, value): + """Set Check out time for session + :type value: time + :param value: Checkout time + """ + self._checkout_time = value + + @property + def long_running(self): + """Test if the session is used for long running transaction. + :rtype: bool + :returns: True if session is long running, else False. + """ + return self._long_running + + @long_running.setter + def long_running(self, value): + """Sets if the session is used for long running transaction. + :type value: bool + :param value: bool + """ + self._long_running = value @property def name(self): diff --git a/noxfile.py b/noxfile.py index 05f00f714b..638e431af2 100644 --- a/noxfile.py +++ b/noxfile.py @@ -29,7 +29,7 @@ ISORT_VERSION = "isort==5.10.1" LINT_PATHS = ["docs", "google", "tests", "noxfile.py", "setup.py"] -DEFAULT_PYTHON_VERSION = "3.8" +DEFAULT_PYTHON_VERSION = "3.9" UNIT_TEST_PYTHON_VERSIONS = ["3.7", "3.8", "3.9", "3.10", "3.11"] UNIT_TEST_STANDARD_DEPENDENCIES = [ @@ -45,7 +45,7 @@ UNIT_TEST_EXTRAS = [] UNIT_TEST_EXTRAS_BY_PYTHON = {} -SYSTEM_TEST_PYTHON_VERSIONS = ["3.8"] +SYSTEM_TEST_PYTHON_VERSIONS = ["3.9"] SYSTEM_TEST_STANDARD_DEPENDENCIES = [ "mock", "pytest", diff --git a/samples/samples/batchinsert.py b/samples/samples/batchinsert.py new file mode 100644 index 0000000000..d70d252490 --- /dev/null +++ b/samples/samples/batchinsert.py @@ -0,0 +1,32 @@ + +from google.cloud import spanner +import _thread +import pdb +import logging +logging.getLogger().addHandler(logging.FileHandler('logsSurbhi.log')) +logging.getLogger().setLevel(logging.DEBUG) +def batch_write(prefix): + client = spanner.Client() + instance = client.instance('surbhi-testing') + database = instance.database('test-db') + for i in range(1): + values = [(prefix+str(i * 1000 + j).zfill(6), 'FN'+prefix+str( + i * 1000 + j).zfill(6), 'LN'+prefix+str( + i * 1000 + j).zfill(6)) for j in range(1000)] + with database.batch() as batch: + batch.insert_or_update( + table='SingersABC', + columns=('SingerId','FirstName','LastName'), + values=values + ) + print(u'Inserted batch {}'.format(prefix+str(i))) + +if __name__ == "__main__": + try: + for prefix in 'abcdefghijklmnopqrstuvwxyz': + _thread.start_new_thread(batch_write,(prefix,)) + print('started Thread' + prefix) + except: + print('Unable to start new thread') + while 1: + pass \ No newline at end of file diff --git a/samples/samples/snippets.py b/samples/samples/snippets.py index a447121010..66cbfaa7fe 100644 --- a/samples/samples/snippets.py +++ b/samples/samples/snippets.py @@ -808,7 +808,29 @@ def read_only_transaction(instance_id, database_id): for row in results: print("SingerId: {}, AlbumId: {}, AlbumTitle: {}".format(*row)) - +def jsonTest(): + print("jsontest") + import pdb + pdb.set_trace() + print(184.909685677713) + print(184.90968567771299) + spanner_client = spanner.Client() + instance = spanner_client.instance("surbhi-testing") + database = instance.database("test-db") + with database.snapshot(multi_use=True) as snapshot: + # Read using SQL. + results = snapshot.execute_sql( + "select PARSE_JSON('{\"bob\": 184.909685677713}', wide_number_mode=>'round')" + ) + + for row in results: + print(row) + # def update_albums(transaction): + # # Read the second album budget. + # second_album_result = transaction.execute_update( + # "select PARSE_JSON('{'bob': 184.909685677713}', wide_number_mode=>'round') as json_data" + # ) + # database.run_in_transaction(update_albums) # [END spanner_read_only_transaction] @@ -2452,6 +2474,7 @@ def enable_fine_grained_access( ) subparsers.add_parser("read_write_transaction", help=read_write_transaction.__doc__) subparsers.add_parser("read_only_transaction", help=read_only_transaction.__doc__) + subparsers.add_parser("jsonTest", help=jsonTest.__doc__) subparsers.add_parser("add_index", help=add_index.__doc__) query_data_with_index_parser = subparsers.add_parser( "query_data_with_index", help=query_data_with_index.__doc__ @@ -2581,6 +2604,8 @@ def enable_fine_grained_access( read_write_transaction(args.instance_id, args.database_id) elif args.command == "read_only_transaction": read_only_transaction(args.instance_id, args.database_id) + elif args.command == "jsonTest": + jsonTest() elif args.command == "add_index": add_index(args.instance_id, args.database_id) elif args.command == "query_data_with_index": diff --git a/samples/samples/snippets_test.py b/samples/samples/snippets_test.py index 6d5822e37b..2f23d26a7f 100644 --- a/samples/samples/snippets_test.py +++ b/samples/samples/snippets_test.py @@ -392,6 +392,12 @@ def test_read_only_transaction(capsys, instance_id, sample_database): # Snippet does two reads, so entry should be listed twice assert out.count("SingerId: 1, AlbumId: 1, AlbumTitle: Total Junk") == 2 +def test_jsonTest(capsys): + snippets.jsonTest() + out, _ = capsys.readouterr() + # Snippet does two reads, so entry should be listed twice + #assert out.count("SingerId: 1, AlbumId: 1, AlbumTitle: Total Junk") == 2 + @pytest.mark.dependency(name="add_timestamp_column", depends=["insert_data"]) def test_add_timestamp_column(capsys, instance_id, sample_database): diff --git a/test.py b/test.py index 6032524b04..abbdfa3705 100644 --- a/test.py +++ b/test.py @@ -1,11 +1,55 @@ from google.cloud import spanner -from gooogle.cloud.spanner_v1 import RequestOptions +from google.cloud.spanner import TransactionPingingPool +from google.cloud.spanner_v1 import param_types +pool = TransactionPingingPool(size=30, default_timeout=5, ping_interval=300) client = spanner.Client() -instance = client.instance('test-instance') -database = instance.database('test-db') +instance = client.instance('surbhi-testing') +database = instance.database('test-db', pool=pool) -with database.snapshot() as snapshot: - results = snapshot.execute_sql("SELECT * in all_types LIMIT %s", ) +def unit_of_Work(transaction, id): + + # transaction.update( + # table="Singers", + # columns=("SingerId", "FirstName"), + # values=[(id, "Surbhi1")], + # ) + # row_ct = transaction.execute_update( + # "INSERT Singers (SingerId, FirstName, LastName) " + # " VALUES ({id}, 'Virginia {id}', 'Watson {id}')".format(id=id) + # ) + # print("{} record(s) inserted.".format(row_ct)) + + results = transaction.execute_sql( + "SELECT FirstName, LastName FROM Singers WHERE SingerId = {id}".format(id=id) + ) + + for result in results: + print("FirstName: {}, LastName: {}".format(*result)) + + row_ct = transaction.execute_update( + "UPDATE Singers SET LastName = 'Grant' " + "WHERE SingerId = {id}".format(id=id) + ) + print("{} record(s) updated.".format(row_ct)) + + results = transaction.execute_sql( + "SELECT FirstName, LastName FROM Singers WHERE SingerId = {id}".format(id=id) + ) + + for result in results: + print("FirstName: {}, LastName: {}".format(*result)) + +def execute_transaction(): + database.run_in_transaction(unit_of_Work, id=20) +# singerid = 17 + +# while singerid < 67: +# database.run_in_transaction(unit_of_Work, id=singerid) +# singerid = singerid +1 +import timeit +num_runs = 10 +num_repetions = 3 +ex_time = timeit.Timer(execute_transaction).repeat(repeat=num_repetions, number = num_runs) +print(f'It took {ex_time}') -database.drop() \ No newline at end of file diff --git a/tests/unit/test_database.py b/tests/unit/test_database.py index d070628aac..f885092795 100644 --- a/tests/unit/test_database.py +++ b/tests/unit/test_database.py @@ -2703,7 +2703,7 @@ class _Pool(object): def bind(self, database): self._bound = database - def get(self): + def get(self, isLongRunning=False): session, self._session = self._session, None return session diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 58665634de..40134c4d93 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -15,6 +15,7 @@ from functools import total_ordering import unittest +from time import sleep import mock @@ -131,6 +132,19 @@ def test_session_w_kwargs(self): self.assertIsNone(checkout._session) self.assertEqual(checkout._kwargs, {"foo": "bar"}) + def test_startCleaningLongRunningSessions(self): + pool = self._make_one() + import pdb + pdb.set_trace() + pool.startCleaningLongRunningSessions() + self.assertEqual(pool._cleanup_task_ongoing, True) + sleep(20) + pdb.set_trace() + + def test_stopCleaningLongRunningSessions(self): + pool = self._make_one + pool.stopCleaningLongRunningSessions() + self.assertTrue(pool._stop_cleanup_transactions_event.is_set()) class TestFixedSizePool(unittest.TestCase): def _getTargetClass(self): @@ -778,7 +792,7 @@ def test_put_non_full_w_active_txn(self): database = _Database("name") session = _Session(database) txn = session.transaction() - + pool.bind(database) pool.put(session) self.assertEqual(len(session_queue._items), 1) @@ -792,8 +806,10 @@ def test_put_non_full_w_committed_txn(self): pool = self._make_one(size=1) session_queue = pool._sessions = _Queue() pending = pool._pending_sessions = _Queue() + database = _Database("name") session = _Session(database) + database._sessions.extend([session]) committed = session.transaction() committed.committed = True @@ -958,6 +974,8 @@ def __init__(self, name): self._database_role = None self.database_id = name self._route_to_leader_enabled = True + self.close_inactive_transactions = True + self.logging_enabled = False def mock_batch_create_sessions( request=None, From 920eb55f7c4d12ea610239a7e0ed41380b3e97b9 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Tue, 13 Jun 2023 11:43:14 +0530 Subject: [PATCH 02/24] unit tests and logging --- google/cloud/spanner_dbapi/connection.py | 2 +- google/cloud/spanner_v1/database.py | 4 +- google/cloud/spanner_v1/instance.py | 4 + google/cloud/spanner_v1/pool.py | 38 ++- google/cloud/spanner_v1/session.py | 16 ++ samples/samples/batchinsert.py | 32 --- samples/samples/snippets.py | 27 +-- samples/samples/snippets_test.py | 6 - tests/unit/spanner_dbapi/test_connect.py | 4 +- tests/unit/spanner_dbapi/test_connection.py | 8 +- tests/unit/test_database.py | 53 +++++ tests/unit/test_pool.py | 242 +++++++++++++++++--- 12 files changed, 320 insertions(+), 116 deletions(-) delete mode 100644 samples/samples/batchinsert.py diff --git a/google/cloud/spanner_dbapi/connection.py b/google/cloud/spanner_dbapi/connection.py index e6a0610baf..681d6a0a6c 100644 --- a/google/cloud/spanner_dbapi/connection.py +++ b/google/cloud/spanner_dbapi/connection.py @@ -583,7 +583,7 @@ def connect( instance = client.instance(instance_id) conn = Connection( - instance, instance.database(database_id, pool=pool) if database_id else None + instance, instance.database(database_id, pool=pool, logging_enabled=False, close_inactive_transactions=False) if database_id else None ) if pool is not None: conn._own_pool = False diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index 5b1778826e..cd27277a93 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -20,7 +20,6 @@ import logging import re import threading -import logging import google.auth.credentials from google.api_core.retry import Retry @@ -142,7 +141,7 @@ def __init__( instance, ddl_statements=(), pool=None, - logging_enabled=False, + logging_enabled=True, logger=None, close_inactive_transactions=True, encryption_config=None, @@ -1059,7 +1058,6 @@ def __exit__(self, exc_type, exc_val, exc_tb): "CommitStats: {}".format(self._batch.commit_stats), extra={"commit_stats": self._batch.commit_stats}, ) - logging.debug("Session details {}".format(self._session.checkout_time)) self._database._pool.put(self._session) diff --git a/google/cloud/spanner_v1/instance.py b/google/cloud/spanner_v1/instance.py index 1b426f8cc2..3625ee0a88 100644 --- a/google/cloud/spanner_v1/instance.py +++ b/google/cloud/spanner_v1/instance.py @@ -428,7 +428,9 @@ def database( database_id, ddl_statements=(), pool=None, + logging_enabled=True, logger=None, + close_inactive_transactions=False, encryption_config=None, database_dialect=DatabaseDialect.DATABASE_DIALECT_UNSPECIFIED, database_role=None, @@ -480,7 +482,9 @@ def database( self, ddl_statements=ddl_statements, pool=pool, + logging_enabled=logging_enabled, logger=logger, + close_inactive_transactions=close_inactive_transactions, encryption_config=encryption_config, database_dialect=database_dialect, database_role=database_role, diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index a77dc8b434..29d44bbbc8 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -151,31 +151,44 @@ def session(self, **kwargs): def startCleaningLongRunningSessions(self): if not AbstractSessionPool._cleanup_task_ongoing_event.is_set() and not AbstractSessionPool._cleanup_task_ongoing: AbstractSessionPool._cleanup_task_ongoing_event.set() - background = threading.Thread(target=self.deleteLongRunningTransactions, args=(120,), daemon=True, name='recycle-sessions') + background = threading.Thread(target=self.deleteLongRunningTransactions, args=(120, 3600,), daemon=True, name='recycle-sessions') background.start() def stopCleaningLongRunningSessions(self): AbstractSessionPool._cleanup_task_ongoing_event.clear() + AbstractSessionPool._cleanup_task_ongoing = False - def deleteLongRunningTransactions(self, interval_sec): + def deleteLongRunningTransactions(self, interval_sec, timeout_sec): + long_running_transaction_timer = time.time() + transactions_closed = 0 while AbstractSessionPool._cleanup_task_ongoing_event.is_set(): + if (time.time() - long_running_transaction_timer >= timeout_sec) and transactions_closed == 0: + break AbstractSessionPool._cleanup_task_ongoing = True - logging.debug("delete long running started") start = time.time() sessions_to_delete = (session for session in self._borrowed_sessions if (datetime.datetime.utcnow() - session.checkout_time > datetime.timedelta(minutes=60)) and not session.long_running) for session in sessions_to_delete: - if self._database.logging_enabled: - self._database.logger.warn("Removing long runinng sess") if self._database.close_inactive_transactions: + if self._database.logging_enabled: + self._database.logger.warn('Long running transaction! Transaction has been closed as it was running for ' + + 'more than 60 minutes. For long running transactions use batch or partitioned transactions.') + if session._transaction is not None: + session._transaction._session = None + transactions_closed += 1 self.put(session) + elif self._database.logging_enabled: + if not session.transaction_logged: + self._database.logger.warn('Transaction has been running for longer than 60 minutes and might be causing a leak. ' + + 'Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions.') + session.transaction_logged = True elapsed_time = time.time() - start if interval_sec - elapsed_time > 0: time.sleep(interval_sec - elapsed_time) - logging.debug("setting flag as False") AbstractSessionPool._cleanup_task_ongoing = False + AbstractSessionPool._cleanup_task_ongoing_event.clear() class FixedSizePool(AbstractSessionPool): """Concrete session pool implementation: @@ -221,6 +234,7 @@ def __init__( self.size = size self.default_timeout = default_timeout self._sessions = queue.LifoQueue(size) + self._borrowed_sessions = [] def bind(self, database): """Associate the pool with a database. @@ -274,6 +288,7 @@ def get(self, isLongRunning=False, timeout=None): session.checkout_time = datetime.datetime.utcnow() session.long_running = isLongRunning + session.transaction_logged = False self._borrowed_sessions.append(session) if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : self.startCleaningLongRunningSessions() @@ -336,6 +351,7 @@ def __init__(self, target_size=10, labels=None, database_role=None): self.target_size = target_size self._database = None self._sessions = queue.LifoQueue(target_size) + self._borrowed_sessions = [] def bind(self, database): """Associate the pool with a database. @@ -365,11 +381,10 @@ def get(self, isLongRunning=False): session.create() session.checkout_time = datetime.datetime.utcnow() session.long_running = isLongRunning + session.transaction_logged = False self._borrowed_sessions.append(session) - if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.target_size >= 0.55 : + if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.target_size >= 0.95 : self.startCleaningLongRunningSessions() - if self._database.logging_enabled: - print("log") return session def put(self, session): @@ -456,6 +471,7 @@ def __init__( self.default_timeout = default_timeout self._delta = datetime.timedelta(seconds=ping_interval) self._sessions = queue.PriorityQueue(size) + self._borrowed_sessions = [] def bind(self, database): """Associate the pool with a database. @@ -517,11 +533,10 @@ def get(self, isLongRunning=False, timeout=None): session.checkout_time = datetime.datetime.utcnow() session.long_running = isLongRunning + session.transaction_logged = False self._borrowed_sessions.append(session) if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : self.startCleaningLongRunningSessions() - if self._database.logging_enabled: - print("log") return session def put(self, session): @@ -623,6 +638,7 @@ def __init__( stacklevel=2, ) self._pending_sessions = queue.Queue() + self._borrowed_sessions = [] super(TransactionPingingPool, self).__init__( size, diff --git a/google/cloud/spanner_v1/session.py b/google/cloud/spanner_v1/session.py index 8453df848a..95702ad4c1 100644 --- a/google/cloud/spanner_v1/session.py +++ b/google/cloud/spanner_v1/session.py @@ -127,6 +127,22 @@ def long_running(self, value): """ self._long_running = value + @property + def transaction_logged(self): + """Test if the session is already logged for long running transaction. + :rtype: bool + :returns: True if session is already logged for long running, else False. + """ + return self._transaction_logged + + @transaction_logged.setter + def transaction_logged(self, value): + """Sets if the session is already logged for long running transaction. + :type value: bool + :param value: bool + """ + self._transaction_logged = value + @property def name(self): """Session name used in requests. diff --git a/samples/samples/batchinsert.py b/samples/samples/batchinsert.py deleted file mode 100644 index d70d252490..0000000000 --- a/samples/samples/batchinsert.py +++ /dev/null @@ -1,32 +0,0 @@ - -from google.cloud import spanner -import _thread -import pdb -import logging -logging.getLogger().addHandler(logging.FileHandler('logsSurbhi.log')) -logging.getLogger().setLevel(logging.DEBUG) -def batch_write(prefix): - client = spanner.Client() - instance = client.instance('surbhi-testing') - database = instance.database('test-db') - for i in range(1): - values = [(prefix+str(i * 1000 + j).zfill(6), 'FN'+prefix+str( - i * 1000 + j).zfill(6), 'LN'+prefix+str( - i * 1000 + j).zfill(6)) for j in range(1000)] - with database.batch() as batch: - batch.insert_or_update( - table='SingersABC', - columns=('SingerId','FirstName','LastName'), - values=values - ) - print(u'Inserted batch {}'.format(prefix+str(i))) - -if __name__ == "__main__": - try: - for prefix in 'abcdefghijklmnopqrstuvwxyz': - _thread.start_new_thread(batch_write,(prefix,)) - print('started Thread' + prefix) - except: - print('Unable to start new thread') - while 1: - pass \ No newline at end of file diff --git a/samples/samples/snippets.py b/samples/samples/snippets.py index b6da90ceb3..57590551ad 100644 --- a/samples/samples/snippets.py +++ b/samples/samples/snippets.py @@ -829,29 +829,7 @@ def read_only_transaction(instance_id, database_id): for row in results: print("SingerId: {}, AlbumId: {}, AlbumTitle: {}".format(*row)) -def jsonTest(): - print("jsontest") - import pdb - pdb.set_trace() - print(184.909685677713) - print(184.90968567771299) - spanner_client = spanner.Client() - instance = spanner_client.instance("surbhi-testing") - database = instance.database("test-db") - with database.snapshot(multi_use=True) as snapshot: - # Read using SQL. - results = snapshot.execute_sql( - "select PARSE_JSON('{\"bob\": 184.909685677713}', wide_number_mode=>'round')" - ) - - for row in results: - print(row) - # def update_albums(transaction): - # # Read the second album budget. - # second_album_result = transaction.execute_update( - # "select PARSE_JSON('{'bob': 184.909685677713}', wide_number_mode=>'round') as json_data" - # ) - # database.run_in_transaction(update_albums) + # [END spanner_read_only_transaction] @@ -2495,7 +2473,6 @@ def enable_fine_grained_access( ) subparsers.add_parser("read_write_transaction", help=read_write_transaction.__doc__) subparsers.add_parser("read_only_transaction", help=read_only_transaction.__doc__) - subparsers.add_parser("jsonTest", help=jsonTest.__doc__) subparsers.add_parser("add_index", help=add_index.__doc__) query_data_with_index_parser = subparsers.add_parser( "query_data_with_index", help=query_data_with_index.__doc__ @@ -2625,8 +2602,6 @@ def enable_fine_grained_access( read_write_transaction(args.instance_id, args.database_id) elif args.command == "read_only_transaction": read_only_transaction(args.instance_id, args.database_id) - elif args.command == "jsonTest": - jsonTest() elif args.command == "add_index": add_index(args.instance_id, args.database_id) elif args.command == "query_data_with_index": diff --git a/samples/samples/snippets_test.py b/samples/samples/snippets_test.py index 89ad364fb2..b8e1e093a1 100644 --- a/samples/samples/snippets_test.py +++ b/samples/samples/snippets_test.py @@ -405,12 +405,6 @@ def test_read_only_transaction(capsys, instance_id, sample_database): # Snippet does two reads, so entry should be listed twice assert out.count("SingerId: 1, AlbumId: 1, AlbumTitle: Total Junk") == 2 -def test_jsonTest(capsys): - snippets.jsonTest() - out, _ = capsys.readouterr() - # Snippet does two reads, so entry should be listed twice - #assert out.count("SingerId: 1, AlbumId: 1, AlbumTitle: Total Junk") == 2 - @pytest.mark.dependency(name="add_timestamp_column", depends=["insert_data"]) def test_add_timestamp_column(capsys, instance_id, sample_database): diff --git a/tests/unit/spanner_dbapi/test_connect.py b/tests/unit/spanner_dbapi/test_connect.py index a5b520bcbf..cfb73ea820 100644 --- a/tests/unit/spanner_dbapi/test_connect.py +++ b/tests/unit/spanner_dbapi/test_connect.py @@ -53,7 +53,7 @@ def test_w_implicit(self, mock_client): client.instance.assert_called_once_with(INSTANCE) self.assertIs(connection.database, database) - instance.database.assert_called_once_with(DATABASE, pool=None) + instance.database.assert_called_once_with(DATABASE, pool=None, logging_enabled=False, close_inactive_transactions=False) # Datbase constructs its own pool self.assertIsNotNone(connection.database._pool) self.assertTrue(connection.instance._client.route_to_leader_enabled) @@ -96,7 +96,7 @@ def test_w_explicit(self, mock_client): client.instance.assert_called_once_with(INSTANCE) self.assertIs(connection.database, database) - instance.database.assert_called_once_with(DATABASE, pool=pool) + instance.database.assert_called_once_with(DATABASE, pool=pool, logging_enabled=False, close_inactive_transactions=False) def test_w_credential_file_path(self, mock_client): from google.cloud.spanner_dbapi import connect diff --git a/tests/unit/spanner_dbapi/test_connection.py b/tests/unit/spanner_dbapi/test_connection.py index 1628f84062..54bb455e46 100644 --- a/tests/unit/spanner_dbapi/test_connection.py +++ b/tests/unit/spanner_dbapi/test_connection.py @@ -1000,11 +1000,13 @@ def __init__(self, name="instance_id", client=None): self.name = name self._client = client - def database(self, database_id="database_id", pool=None): - return _Database(database_id, pool) + def database(self, database_id="database_id", pool=None, logging_enabled=False, close_inactive_transactions=False): + return _Database(database_id, pool, logging_enabled=False, close_inactive_transactions=False) class _Database(object): - def __init__(self, database_id="database_id", pool=None): + def __init__(self, database_id="database_id", pool=None, logging_enabled=False, close_inactive_transactions=False): self.name = database_id self.pool = pool + self.logging_enabled = logging_enabled + self.close_inactive_transactions = close_inactive_transactions diff --git a/tests/unit/test_database.py b/tests/unit/test_database.py index e299726d26..8356a56b9a 100644 --- a/tests/unit/test_database.py +++ b/tests/unit/test_database.py @@ -117,6 +117,8 @@ def test_ctor_defaults(self): self.assertTrue(database._pool._sessions.empty()) self.assertIsNone(database.database_role) self.assertTrue(database._route_to_leader_enabled, True) + self.assertTrue(database._logging_enabled) + self.assertFalse(database._close_inactive_transactions) def test_ctor_w_explicit_pool(self): instance = _Instance(self.INSTANCE_NAME) @@ -147,6 +149,42 @@ def test_ctor_w_route_to_leader_disbled(self): self.assertIs(database._instance, instance) self.assertFalse(database._route_to_leader_enabled) + def test_ctor_w_logger_enabled(self): + instance = _Instance(self.INSTANCE_NAME) + database = self._make_one( + self.DATABASE_ID, instance, logging_enabled=True + ) + self.assertEqual(database.database_id, self.DATABASE_ID) + self.assertIs(database._instance, instance) + self.assertIs(database.logging_enabled, True) + + def test_ctor_w_logger_disabled(self): + instance = _Instance(self.INSTANCE_NAME) + database = self._make_one( + self.DATABASE_ID, instance, logging_enabled=False + ) + self.assertEqual(database.database_id, self.DATABASE_ID) + self.assertIs(database._instance, instance) + self.assertIs(database.logging_enabled, False) + + def test_ctor_w_close_inactive_transactions_enabled(self): + instance = _Instance(self.INSTANCE_NAME) + database = self._make_one( + self.DATABASE_ID, instance, close_inactive_transactions=True + ) + self.assertEqual(database.database_id, self.DATABASE_ID) + self.assertIs(database._instance, instance) + self.assertIs(database.close_inactive_transactions, True) + + def test_ctor_w_close_inactive_transactions_disabled(self): + instance = _Instance(self.INSTANCE_NAME) + database = self._make_one( + self.DATABASE_ID, instance, close_inactive_transactions=False + ) + self.assertEqual(database.database_id, self.DATABASE_ID) + self.assertIs(database._instance, instance) + self.assertIs(database.close_inactive_transactions, False) + def test_ctor_w_ddl_statements_non_string(self): with self.assertRaises(ValueError): @@ -1202,6 +1240,20 @@ def test_snapshot_defaults(self): self.assertIs(checkout._database, database) self.assertEqual(checkout._kw, {}) + def test_snapshot_longrunningvalue(self): + from google.cloud.spanner_v1.snapshot import Snapshot + + client = _Client() + instance = _Instance(self.INSTANCE_NAME, client=client) + pool = mock.Mock() + database = self._make_one(self.DATABASE_ID, instance, pool=pool) + with database.snapshot() as checkout: + self.assertIsInstance(checkout, Snapshot) + + self.assertEqual(pool.get.call_count, 1) + # get method of pool is passed without any param, that means longrunning param is false + pool.get.assert_called_once_with() + def test_snapshot_w_read_timestamp_and_multi_use(self): import datetime from google.cloud._helpers import UTC @@ -2737,6 +2789,7 @@ def bind(self, database): def get(self, isLongRunning=False): session, self._session = self._session, None + session.long_running = isLongRunning return session def put(self, session): diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 40134c4d93..d0e585be3d 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -16,9 +16,9 @@ from functools import total_ordering import unittest from time import sleep - +import threading import mock - +import datetime def _make_database(name="name"): from google.cloud.spanner_v1.database import Database @@ -132,19 +132,117 @@ def test_session_w_kwargs(self): self.assertIsNone(checkout._session) self.assertEqual(checkout._kwargs, {"foo": "bar"}) - def test_startCleaningLongRunningSessions(self): + @mock.patch('threading.Thread') + def test_startCleaningLongRunningSessions_success(self, mock_thread_class): + mock_thread = mock.MagicMock() + mock_thread.start = mock.MagicMock() + mock_thread_class.return_value = mock_thread + pool = self._make_one() - import pdb - pdb.set_trace() + pool._cleanup_task_ongoing_event.clear() pool.startCleaningLongRunningSessions() - self.assertEqual(pool._cleanup_task_ongoing, True) - sleep(20) - pdb.set_trace() + # The event should be set, indicating the task is now ongoing + self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) + + # A new thread should have been created to start the task + threading.Thread.assert_called_once_with( + target=pool.deleteLongRunningTransactions, + args=(120, 3600), + daemon=True, + name='recycle-sessions' + ) + mock_thread.start.assert_called_once() + pool.stopCleaningLongRunningSessions() + def test_stopCleaningLongRunningSessions(self): - pool = self._make_one + pool = self._make_one() + pool._cleanup_task_ongoing_event.set() pool.stopCleaningLongRunningSessions() - self.assertTrue(pool._stop_cleanup_transactions_event.is_set()) + + # The event should not be set, indicating the task is now stopped + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + + + def _setup_session_leak(self, close_inactive_transactions, logging_enabled): + pool = self._make_one() + pool._database = mock.MagicMock() + pool.put = mock.MagicMock() + def put_side_effect(*args, **kwargs): + pool._borrowed_sessions = [] + pool._cleanup_task_ongoing_event.clear() + + pool.put.side_effect = put_side_effect + + pool._database.logging_enabled = logging_enabled + pool._cleanup_task_ongoing_event.set() + pool._database.close_inactive_transactions = close_inactive_transactions + pool._borrowed_sessions = [] + pool._database.logger.warn = mock.MagicMock() + return pool + + def test_deleteLongRunningTransactions_noSessionsToDelete(self): + pool = self._setup_session_leak(True, True) + pool.deleteLongRunningTransactions(1, 1) + + # Assert that no warnings were logged and no sessions were put back + self.assertEqual(pool._database.logger.warn.call_count, 0) + pool.put.assert_not_called() + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + + def test_deleteLongRunningTransactions_deleteAndLogSession(self): + pool = self._setup_session_leak(True, True) + # Create a session that needs to be closed + session = mock.MagicMock() + session.transaction_logged = False + session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) + session.long_running = False + pool._borrowed_sessions = [session] + pool._cleanup_task_ongoing_event.set() + # Call deleteLongRunningTransactions + pool.deleteLongRunningTransactions(2, 2) + + # Assert that the session was put back and a warning was logged + pool.put.assert_called_once() + pool._database.logger.warn.assert_called_once() + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + + def test_deleteLongRunningTransactions_logSession(self): + pool = self._setup_session_leak(False, True) + # Create a session that needs to be closed + session = mock.MagicMock() + session.transaction_logged = False + session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) + session.long_running = False + pool._borrowed_sessions = [session] + pool._cleanup_task_ongoing_event.set() + # Call deleteLongRunningTransactions + pool.deleteLongRunningTransactions(2, 2) + + # Assert that the session was not put back and a warning was logged + pool.put.assert_not_called() + pool._database.logger.warn.assert_called_once() + self.assertTrue(session.transaction_logged) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + + def test_deleteLongRunningTransactions_deleteSession(self): + pool = self._setup_session_leak(True, False) + # Create a session that needs to be closed + session = mock.MagicMock() + session.transaction_logged = False + session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) + session.long_running = False + pool._borrowed_sessions = [session] + pool._cleanup_task_ongoing_event.set() + # Call deleteLongRunningTransactions + pool.deleteLongRunningTransactions(2, 2) + + # Assert that the session was not put back and a warning was logged + pool.put.assert_called_once() + pool._database.logger.warn.assert_not_called() + self.assertFalse(session.transaction_logged) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + class TestFixedSizePool(unittest.TestCase): def _getTargetClass(self): @@ -227,6 +325,28 @@ def test_get_expired(self): self.assertTrue(SESSIONS[0]._exists_checked) self.assertFalse(pool._sessions.full()) + def test_get_longrunning_defaults(self): + pool = self._make_one(size=2) + database = _Database("name") + SESSIONS = [_Session(database)] * 3 + for session in SESSIONS: + session._exists = True + database._sessions.extend(SESSIONS) + pool.bind(database) + session = pool.get() + self.assertIsInstance(session.checkout_time, datetime.datetime) + self.assertFalse(session.long_running) + self.assertFalse(session.transaction_logged) + self.assertIs(session, pool._borrowed_sessions[0]) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + + # Fetch new session which will trigger the cleanup task. + session1 = pool.get() + self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) + + pool.stopCleaningLongRunningSessions() + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + def test_get_empty_default_timeout(self): import queue @@ -271,8 +391,14 @@ def test_put_non_full(self): pool.bind(database) pool._sessions.get() - pool.put(_Session(database)) + session = _Session(database) + pool._borrowed_sessions.append(session) + pool._cleanup_task_ongoing_event.set() + pool.put(session) + + self.assertEqual(len(pool._borrowed_sessions), 0) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) self.assertTrue(pool._sessions.full()) def test_clear(self): @@ -342,6 +468,28 @@ def test_get_empty(self): session.create.assert_called() self.assertTrue(pool._sessions.empty()) + def test_get_longrunning_defaults(self): + pool = self._make_one(target_size=2) + database = _Database("name") + SESSIONS = [_Session(database)] * 3 + database._sessions.extend(SESSIONS) + pool.bind(database) + + session = pool.get() + session.create.assert_called() + self.assertIsInstance(session.checkout_time, datetime.datetime) + self.assertFalse(session.long_running) + self.assertFalse(session.transaction_logged) + self.assertTrue(len(pool._borrowed_sessions), 1) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + + # Fetch new session which will trigger the cleanup task. + session1 = pool.get() + self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) + + pool.stopCleaningLongRunningSessions() + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + def test_get_non_empty_session_exists(self): pool = self._make_one() database = _Database("name") @@ -378,9 +526,13 @@ def test_put_empty(self): database = _Database("name") pool.bind(database) session = _Session(database) + pool._borrowed_sessions.append(session) + pool._cleanup_task_ongoing_event.set() pool.put(session) + self.assertEqual(len(pool._borrowed_sessions), 0) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) self.assertFalse(pool._sessions.empty()) def test_put_full(self): @@ -397,20 +549,6 @@ def test_put_full(self): self.assertTrue(younger._deleted) self.assertIs(pool.get(), older) - def test_put_full_expired(self): - pool = self._make_one(target_size=1) - database = _Database("name") - pool.bind(database) - older = _Session(database) - pool.put(older) - self.assertFalse(pool._sessions.empty()) - - younger = _Session(database, exists=False) - pool.put(younger) # discarded silently - - self.assertTrue(younger._deleted) - self.assertIs(pool.get(), older) - def test_clear(self): pool = self._make_one() database = _Database("name") @@ -501,6 +639,27 @@ def test_get_hit_no_ping(self): self.assertFalse(session._exists_checked) self.assertFalse(pool._sessions.full()) + def test_get_longrunning_defaults(self): + pool = self._make_one(size=2) + database = _Database("name") + SESSIONS = [_Session(database)] * 3 + database._sessions.extend(SESSIONS) + pool.bind(database) + session = pool.get() + self.assertIsInstance(session.checkout_time, datetime.datetime) + self.assertFalse(session.long_running) + self.assertFalse(session.transaction_logged) + self.assertTrue(len(pool._borrowed_sessions), 1) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + + # Fetch new session which will trigger the cleanup task. + session1 = pool.get() + self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) + + # Stop the background task. + pool.stopCleaningLongRunningSessions() + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + def test_get_hit_w_ping(self): import datetime from google.cloud._testing import _Monkey @@ -588,14 +747,19 @@ def test_put_non_full(self): pool = self._make_one(size=1) session_queue = pool._sessions = _Queue() - + now = datetime.datetime.utcnow() database = _Database("name") session = _Session(database) - + pool._borrowed_sessions.append(session) + pool._database = database + pool._cleanup_task_ongoing_event.set() with _Monkey(MUT, _NOW=lambda: now): pool.put(session) + self.assertEqual(len(pool._borrowed_sessions), 0) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + self.assertEqual(len(session_queue._items), 1) ping_after, queued = session_queue._items[0] self.assertEqual(ping_after, now + datetime.timedelta(seconds=3000)) @@ -792,7 +956,9 @@ def test_put_non_full_w_active_txn(self): database = _Database("name") session = _Session(database) txn = session.transaction() - pool.bind(database) + pool._borrowed_sessions.append(session) + pool._cleanup_task_ongoing_event.set() + pool._database = database pool.put(session) self.assertEqual(len(session_queue._items), 1) @@ -800,6 +966,9 @@ def test_put_non_full_w_active_txn(self): self.assertIs(queued, session) self.assertEqual(len(pending._items), 0) + self.assertEqual(len(pool._borrowed_sessions), 0) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + txn.begin.assert_not_called() def test_put_non_full_w_committed_txn(self): @@ -812,7 +981,9 @@ def test_put_non_full_w_committed_txn(self): database._sessions.extend([session]) committed = session.transaction() committed.committed = True - + pool._borrowed_sessions.append(session) + pool._cleanup_task_ongoing_event.set() + pool._database = database pool.put(session) self.assertEqual(len(session_queue._items), 0) @@ -820,6 +991,9 @@ def test_put_non_full_w_committed_txn(self): self.assertEqual(len(pending._items), 1) self.assertIs(pending._items[0], session) self.assertIsNot(session._transaction, committed) + self.assertEqual(len(pool._borrowed_sessions), 0) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + session._transaction.begin.assert_not_called() def test_put_non_full(self): @@ -828,12 +1002,16 @@ def test_put_non_full(self): pending = pool._pending_sessions = _Queue() database = _Database("name") session = _Session(database) - + pool._database = database + pool._borrowed_sessions.append(session) + pool._cleanup_task_ongoing_event.set() pool.put(session) self.assertEqual(len(session_queue._items), 0) self.assertEqual(len(pending._items), 1) self.assertIs(pending._items[0], session) + self.assertEqual(len(pool._borrowed_sessions), 0) + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) self.assertFalse(pending.empty()) @@ -851,7 +1029,7 @@ def test_begin_pending_transactions_non_empty(self): pending = pool._pending_sessions = _Queue(*PENDING_SESSIONS) self.assertFalse(pending.empty()) - + pool._database = database pool.begin_pending_transactions() # no raise for txn in TRANSACTIONS: @@ -975,7 +1153,7 @@ def __init__(self, name): self.database_id = name self._route_to_leader_enabled = True self.close_inactive_transactions = True - self.logging_enabled = False + self.logging_enabled = True def mock_batch_create_sessions( request=None, From aff17b14db4a161e3d1794ac104b31f5f7f3dfdc Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Tue, 13 Jun 2023 11:46:14 +0530 Subject: [PATCH 03/24] revert test changes --- test.py | 56 ++++++-------------------------------------------------- 1 file changed, 6 insertions(+), 50 deletions(-) diff --git a/test.py b/test.py index abbdfa3705..6032524b04 100644 --- a/test.py +++ b/test.py @@ -1,55 +1,11 @@ from google.cloud import spanner -from google.cloud.spanner import TransactionPingingPool -from google.cloud.spanner_v1 import param_types +from gooogle.cloud.spanner_v1 import RequestOptions -pool = TransactionPingingPool(size=30, default_timeout=5, ping_interval=300) client = spanner.Client() -instance = client.instance('surbhi-testing') -database = instance.database('test-db', pool=pool) +instance = client.instance('test-instance') +database = instance.database('test-db') -def unit_of_Work(transaction, id): - - # transaction.update( - # table="Singers", - # columns=("SingerId", "FirstName"), - # values=[(id, "Surbhi1")], - # ) - # row_ct = transaction.execute_update( - # "INSERT Singers (SingerId, FirstName, LastName) " - # " VALUES ({id}, 'Virginia {id}', 'Watson {id}')".format(id=id) - # ) - # print("{} record(s) inserted.".format(row_ct)) - - results = transaction.execute_sql( - "SELECT FirstName, LastName FROM Singers WHERE SingerId = {id}".format(id=id) - ) - - for result in results: - print("FirstName: {}, LastName: {}".format(*result)) - - row_ct = transaction.execute_update( - "UPDATE Singers SET LastName = 'Grant' " - "WHERE SingerId = {id}".format(id=id) - ) - print("{} record(s) updated.".format(row_ct)) - - results = transaction.execute_sql( - "SELECT FirstName, LastName FROM Singers WHERE SingerId = {id}".format(id=id) - ) - - for result in results: - print("FirstName: {}, LastName: {}".format(*result)) - -def execute_transaction(): - database.run_in_transaction(unit_of_Work, id=20) -# singerid = 17 - -# while singerid < 67: -# database.run_in_transaction(unit_of_Work, id=singerid) -# singerid = singerid +1 -import timeit -num_runs = 10 -num_repetions = 3 -ex_time = timeit.Timer(execute_transaction).repeat(repeat=num_repetions, number = num_runs) -print(f'It took {ex_time}') +with database.snapshot() as snapshot: + results = snapshot.execute_sql("SELECT * in all_types LIMIT %s", ) +database.drop() \ No newline at end of file From f2712513e50b7f022cbcfe1169cca3ccb739b674 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Wed, 14 Jun 2023 13:42:06 +0530 Subject: [PATCH 04/24] tests --- google/cloud/spanner_v1/_helpers.py | 4 +++ google/cloud/spanner_v1/batch.py | 2 ++ google/cloud/spanner_v1/database.py | 38 +++++++++++++++----------- google/cloud/spanner_v1/instance.py | 2 +- google/cloud/spanner_v1/pool.py | 11 ++++++-- google/cloud/spanner_v1/session.py | 2 ++ google/cloud/spanner_v1/snapshot.py | 12 ++++++++ google/cloud/spanner_v1/transaction.py | 10 +++++++ tests/unit/test_pool.py | 14 ++++++++-- 9 files changed, 73 insertions(+), 22 deletions(-) diff --git a/google/cloud/spanner_v1/_helpers.py b/google/cloud/spanner_v1/_helpers.py index 4f708b20cf..f938b96f40 100644 --- a/google/cloud/spanner_v1/_helpers.py +++ b/google/cloud/spanner_v1/_helpers.py @@ -38,6 +38,10 @@ + "numeric has a whole component with precision {}" ) +# Constants +DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC = 120 +DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC = 3600 + def _try_to_coerce_bytes(bytestring): """Try to coerce a byte string into the right thing based on Python diff --git a/google/cloud/spanner_v1/batch.py b/google/cloud/spanner_v1/batch.py index 6b71e6d825..400414f706 100644 --- a/google/cloud/spanner_v1/batch.py +++ b/google/cloud/spanner_v1/batch.py @@ -144,6 +144,8 @@ def _check_state(self): """ if self.committed is not None: raise ValueError("Batch already committed") + if self._session is None: + raise ValueError("Transaction has been closed as it was running for more than 60 minutes") def commit(self, return_commit_stats=False, request_options=None): """Commit mutations to the database. diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index cd27277a93..a0555cafbc 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -1028,7 +1028,7 @@ class BatchCheckout(object): def __init__(self, database, request_options=None): self._database = database - self._session = self._batch = None + self._batch = None if request_options is None: self._request_options = RequestOptions() elif type(request_options) == dict: @@ -1038,11 +1038,12 @@ def __init__(self, database, request_options=None): def __enter__(self): """Begin ``with`` block.""" - session = self._session = self._database._pool.get() - batch = self._batch = Batch(session) + session = self._database._pool.get() + self._batch = Batch(session) + session._batch = self._batch if self._request_options.transaction_tag: - batch.transaction_tag = self._request_options.transaction_tag - return batch + self._batch.transaction_tag = self._request_options.transaction_tag + return self._batch def __exit__(self, exc_type, exc_val, exc_tb): """End ``with`` block.""" @@ -1058,7 +1059,8 @@ def __exit__(self, exc_type, exc_val, exc_tb): "CommitStats: {}".format(self._batch.commit_stats), extra={"commit_stats": self._batch.commit_stats}, ) - self._database._pool.put(self._session) + if self._batch._session is not None: + self._database._pool.put(self._batch._session) class SnapshotCheckout(object): @@ -1081,23 +1083,27 @@ class SnapshotCheckout(object): def __init__(self, database, **kw): self._database = database - self._session = None + self._snapshot = None self._kw = kw def __enter__(self): """Begin ``with`` block.""" - session = self._session = self._database._pool.get() - return Snapshot(session, **self._kw) + session = self._database._pool.get() + self._snapshot = Snapshot(session, **self._kw) + session._snapshot = self._snapshot + return self._snapshot def __exit__(self, exc_type, exc_val, exc_tb): """End ``with`` block.""" - if isinstance(exc_val, NotFound): - # If NotFound exception occurs inside the with block - # then we validate if the session still exists. - if not self._session.exists(): - self._session = self._database._pool._new_session() - self._session.create() - self._database._pool.put(self._session) + # self._snapshot._session is None that means session has been returned by background task + if self._snapshot._session is not None: + if isinstance(exc_val, NotFound): + # If NotFound exception occurs inside the with block + # then we validate if the session still exists. + if not self._snapshot._session.exists(): + self._snapshot._session = self._database._pool._new_session() + self._snapshot._session.create() + self._database._pool.put(self._snapshot._session) class BatchSnapshot(object): diff --git a/google/cloud/spanner_v1/instance.py b/google/cloud/spanner_v1/instance.py index 3625ee0a88..6894707d99 100644 --- a/google/cloud/spanner_v1/instance.py +++ b/google/cloud/spanner_v1/instance.py @@ -430,7 +430,7 @@ def database( pool=None, logging_enabled=True, logger=None, - close_inactive_transactions=False, + close_inactive_transactions=True, encryption_config=None, database_dialect=DatabaseDialect.DATABASE_DIALECT_UNSPECIFIED, database_role=None, diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index 29d44bbbc8..b2e15fa1e4 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -25,6 +25,8 @@ from google.cloud.spanner_v1._helpers import ( _metadata_with_prefix, _metadata_with_leader_aware_routing, + DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, + DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC ) from warnings import warn import logging @@ -151,7 +153,7 @@ def session(self, **kwargs): def startCleaningLongRunningSessions(self): if not AbstractSessionPool._cleanup_task_ongoing_event.is_set() and not AbstractSessionPool._cleanup_task_ongoing: AbstractSessionPool._cleanup_task_ongoing_event.set() - background = threading.Thread(target=self.deleteLongRunningTransactions, args=(120, 3600,), daemon=True, name='recycle-sessions') + background = threading.Thread(target=self.deleteLongRunningTransactions, args=(DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC,), daemon=True, name='recycle-sessions') background.start() def stopCleaningLongRunningSessions(self): @@ -176,6 +178,10 @@ def deleteLongRunningTransactions(self, interval_sec, timeout_sec): 'more than 60 minutes. For long running transactions use batch or partitioned transactions.') if session._transaction is not None: session._transaction._session = None + if session._batch is not None: + session._batch._session = None + if session._snapshot is not None: + session._snapshpt._session = None transactions_closed += 1 self.put(session) elif self._database.logging_enabled: @@ -713,4 +719,5 @@ def __enter__(self): return self._session def __exit__(self, *ignored): - self._pool.put(self._session) + if not (self._session._transaction is not None and self._session._transaction._session is None): + self._pool.put(self._session) diff --git a/google/cloud/spanner_v1/session.py b/google/cloud/spanner_v1/session.py index 95702ad4c1..19ccddea92 100644 --- a/google/cloud/spanner_v1/session.py +++ b/google/cloud/spanner_v1/session.py @@ -62,6 +62,8 @@ class Session(object): _session_id = None _transaction = None + _batch = None + _snapshot = None def __init__(self, database, labels=None, database_role=None): self._database = database diff --git a/google/cloud/spanner_v1/snapshot.py b/google/cloud/spanner_v1/snapshot.py index 6d17bfc386..16a77c6f3b 100644 --- a/google/cloud/spanner_v1/snapshot.py +++ b/google/cloud/spanner_v1/snapshot.py @@ -152,6 +152,10 @@ class _SnapshotBase(_SessionWrapper): _execute_sql_count = 0 _lock = threading.Lock() + def _check_session_state(self): + if self._session is None: + raise ValueError("Transaction has been closed as it was running for more than 60 minutes") + def _make_txn_selector(self): """Helper for :meth:`read` / :meth:`execute_sql`. @@ -231,6 +235,9 @@ def read( for reuse of single-use snapshots, or if a transaction ID is already pending for multiple-use snapshots. """ + + self._check_session_state() + if self._read_request_count > 0: if not self._multi_use: raise ValueError("Cannot re-use single-use snapshot.") @@ -383,6 +390,7 @@ def execute_sql( for reuse of single-use snapshots, or if a transaction ID is already pending for multiple-use snapshots. """ + self._check_session_state() if self._read_request_count > 0: if not self._multi_use: raise ValueError("Cannot re-use single-use snapshot.") @@ -531,6 +539,7 @@ def partition_read( for single-use snapshots, or if a transaction ID is already associated with the snapshot. """ + self._check_session_state() if not self._multi_use: raise ValueError("Cannot use single-use snapshot.") @@ -625,6 +634,7 @@ def partition_query( for single-use snapshots, or if a transaction ID is already associated with the snapshot. """ + self._check_session_state() if not self._multi_use: raise ValueError("Cannot use single-use snapshot.") @@ -793,6 +803,8 @@ def begin(self): if self._read_request_count > 0: raise ValueError("Read-only transaction already pending") + + self._check_session_state() database = self._session._database api = database.spanner_api diff --git a/google/cloud/spanner_v1/transaction.py b/google/cloud/spanner_v1/transaction.py index dee99a0c6f..22a66a4d67 100644 --- a/google/cloud/spanner_v1/transaction.py +++ b/google/cloud/spanner_v1/transaction.py @@ -62,6 +62,10 @@ def __init__(self, session): super(Transaction, self).__init__(session) + def _check_session_state(self): + if self._session is None: + raise ValueError("Transaction has been closed as it was running for more than 60 minutes") + def _check_state(self): """Helper for :meth:`commit` et al. @@ -102,6 +106,7 @@ def _execute_request( :type request: proto :param request: request proto to call the method with """ + self._check_session_state() transaction = self._make_txn_selector() request.transaction = transaction with trace_call(trace_name, session, attributes): @@ -130,6 +135,7 @@ def begin(self): if self.rolled_back: raise ValueError("Transaction is already rolled back") + self._check_session_state() database = self._session._database api = database.spanner_api metadata = _metadata_with_prefix(database.name) @@ -154,6 +160,7 @@ def begin(self): def rollback(self): """Roll back a transaction on the database.""" + self._check_session_state() self._check_state() if self._transaction_id is not None: @@ -198,6 +205,7 @@ def commit(self, return_commit_stats=False, request_options=None): :returns: timestamp of the committed changes. :raises ValueError: if there are no mutations to commit. """ + self._check_session_state() self._check_state() if self._transaction_id is None and len(self._mutations) > 0: self.begin() @@ -331,6 +339,7 @@ def execute_update( :rtype: int :returns: Count of rows affected by the DML statement. """ + self._check_session_state() params_pb = self._make_params_pb(params, param_types) database = self._session._database metadata = _metadata_with_prefix(database.name) @@ -435,6 +444,7 @@ def batch_update(self, statements, request_options=None): statement triggering the error will not have an entry in the list, nor will any statements following that one. """ + self._check_session_state() parsed = [] for statement in statements: if isinstance(statement, str): diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index d0e585be3d..72c612e4ec 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -19,6 +19,10 @@ import threading import mock import datetime +from google.cloud.spanner_v1._helpers import ( + DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, + DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC +) def _make_database(name="name"): from google.cloud.spanner_v1.database import Database @@ -133,6 +137,8 @@ def test_session_w_kwargs(self): self.assertEqual(checkout._kwargs, {"foo": "bar"}) @mock.patch('threading.Thread') + @mock.patch('google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC', 5) + @mock.patch('google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC', 10) def test_startCleaningLongRunningSessions_success(self, mock_thread_class): mock_thread = mock.MagicMock() mock_thread.start = mock.MagicMock() @@ -148,7 +154,7 @@ def test_startCleaningLongRunningSessions_success(self, mock_thread_class): # A new thread should have been created to start the task threading.Thread.assert_called_once_with( target=pool.deleteLongRunningTransactions, - args=(120, 3600), + args=(DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC), daemon=True, name='recycle-sessions' ) @@ -1064,7 +1070,8 @@ def test_ctor_w_kwargs(self): ) def test_context_manager_wo_kwargs(self): - session = object() + database = _Database("name") + session = _Session(database) pool = _Pool(session) checkout = self._make_one(pool) @@ -1080,7 +1087,8 @@ def test_context_manager_wo_kwargs(self): self.assertEqual(pool._got, {}) def test_context_manager_w_kwargs(self): - session = object() + database = _Database("name") + session = _Session(database) pool = _Pool(session) checkout = self._make_one(pool, foo="bar") From 799589ecf88224f5c2e6b1912787f791cc1633d3 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Wed, 14 Jun 2023 16:56:00 +0530 Subject: [PATCH 05/24] revert noxfile chanegs --- noxfile.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/noxfile.py b/noxfile.py index 638e431af2..05f00f714b 100644 --- a/noxfile.py +++ b/noxfile.py @@ -29,7 +29,7 @@ ISORT_VERSION = "isort==5.10.1" LINT_PATHS = ["docs", "google", "tests", "noxfile.py", "setup.py"] -DEFAULT_PYTHON_VERSION = "3.9" +DEFAULT_PYTHON_VERSION = "3.8" UNIT_TEST_PYTHON_VERSIONS = ["3.7", "3.8", "3.9", "3.10", "3.11"] UNIT_TEST_STANDARD_DEPENDENCIES = [ @@ -45,7 +45,7 @@ UNIT_TEST_EXTRAS = [] UNIT_TEST_EXTRAS_BY_PYTHON = {} -SYSTEM_TEST_PYTHON_VERSIONS = ["3.9"] +SYSTEM_TEST_PYTHON_VERSIONS = ["3.8"] SYSTEM_TEST_STANDARD_DEPENDENCIES = [ "mock", "pytest", From 38f71b878c00633caee4959dcaf7b60695379977 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Thu, 15 Jun 2023 12:38:44 +0530 Subject: [PATCH 06/24] tests --- google/cloud/spanner_v1/database.py | 2 +- google/cloud/spanner_v1/instance.py | 2 +- google/cloud/spanner_v1/pool.py | 25 ++++++++--- tests/system/test_session_api.py | 25 +++++++++++ tests/unit/test_batch.py | 8 ++++ tests/unit/test_pool.py | 65 ++++++++++++++++++++--------- tests/unit/test_snapshot.py | 33 +++++++++++++++ tests/unit/test_transaction.py | 16 +++++++ 8 files changed, 149 insertions(+), 27 deletions(-) diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index a0555cafbc..d2af6717f0 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -143,7 +143,7 @@ def __init__( pool=None, logging_enabled=True, logger=None, - close_inactive_transactions=True, + close_inactive_transactions=False, encryption_config=None, database_dialect=DatabaseDialect.DATABASE_DIALECT_UNSPECIFIED, database_role=None, diff --git a/google/cloud/spanner_v1/instance.py b/google/cloud/spanner_v1/instance.py index 6894707d99..3625ee0a88 100644 --- a/google/cloud/spanner_v1/instance.py +++ b/google/cloud/spanner_v1/instance.py @@ -430,7 +430,7 @@ def database( pool=None, logging_enabled=True, logger=None, - close_inactive_transactions=True, + close_inactive_transactions=False, encryption_config=None, database_dialect=DatabaseDialect.DATABASE_DIALECT_UNSPECIFIED, database_role=None, diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index b2e15fa1e4..d3e93451d1 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -25,8 +25,6 @@ from google.cloud.spanner_v1._helpers import ( _metadata_with_prefix, _metadata_with_leader_aware_routing, - DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, - DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC ) from warnings import warn import logging @@ -151,8 +149,14 @@ def session(self, **kwargs): return SessionCheckout(self, **kwargs) def startCleaningLongRunningSessions(self): + from google.cloud.spanner_v1._helpers import ( + DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, + DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC + ) if not AbstractSessionPool._cleanup_task_ongoing_event.is_set() and not AbstractSessionPool._cleanup_task_ongoing: AbstractSessionPool._cleanup_task_ongoing_event.set() + if self._database.logging_enabled: + self._database.logger.info('95%% of the session pool is exhausted') background = threading.Thread(target=self.deleteLongRunningTransactions, args=(DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC,), daemon=True, name='recycle-sessions') background.start() @@ -164,13 +168,15 @@ def deleteLongRunningTransactions(self, interval_sec, timeout_sec): long_running_transaction_timer = time.time() transactions_closed = 0 while AbstractSessionPool._cleanup_task_ongoing_event.is_set(): - if (time.time() - long_running_transaction_timer >= timeout_sec) and transactions_closed == 0: + is_timeout_reached_and_no_transaction_closed = (time.time() - long_running_transaction_timer >= timeout_sec + interval_sec) and transactions_closed == 0 + if is_timeout_reached_and_no_transaction_closed: break + AbstractSessionPool._cleanup_task_ongoing = True start = time.time() - sessions_to_delete = (session for session in self._borrowed_sessions - if (datetime.datetime.utcnow() - session.checkout_time > datetime.timedelta(minutes=60)) - and not session.long_running) + sessions_to_delete = list(filter(lambda session : (datetime.datetime.utcnow() - session.checkout_time > datetime.timedelta(seconds=timeout_sec)) + and not session.long_running, self._borrowed_sessions)) + for session in sessions_to_delete: if self._database.close_inactive_transactions: if self._database.logging_enabled: @@ -298,6 +304,9 @@ def get(self, isLongRunning=False, timeout=None): self._borrowed_sessions.append(session) if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : self.startCleaningLongRunningSessions() + + if self._database.logging_enabled and len(self._borrowed_sessions)/self.size == 1: + self._database.logger.warn('100%% of the session pool is exhausted') return session def put(self, session): @@ -391,6 +400,8 @@ def get(self, isLongRunning=False): self._borrowed_sessions.append(session) if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.target_size >= 0.95 : self.startCleaningLongRunningSessions() + if self._database.logging_enabled and len(self._borrowed_sessions)/self.target_size == 1: + self._database.logger.warn('100%% of the session pool is exhausted') return session def put(self, session): @@ -543,6 +554,8 @@ def get(self, isLongRunning=False, timeout=None): self._borrowed_sessions.append(session) if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : self.startCleaningLongRunningSessions() + if self._database.logging_enabled and len(self._borrowed_sessions)/self.size == 1: + self._database.logger.warn('100%% of the session pool is exhausted') return session def put(self, session): diff --git a/tests/system/test_session_api.py b/tests/system/test_session_api.py index 3fd30958b7..d0d4d0846f 100644 --- a/tests/system/test_session_api.py +++ b/tests/system/test_session_api.py @@ -2516,6 +2516,31 @@ def test_partition_query(sessions_database, not_emulator): assert union == all_data_rows batch_txn.close() +def test_should_close_inactive_transactions(not_emulator, not_postgres, shared_instance, database_operation_timeout, databases_to_delete): + spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC = 2 + spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC = 5 + database_name = _helpers.unique_id("test_longrunning", separator="_") + pool = spanner_v1.BurstyPool(target_size=1) + + temp_db = shared_instance.database( + database_name, + ddl_statements=_helpers.DDL_STATEMENTS, + pool=pool, + close_inactive_transactions=True, + logging_enabled=True + ) + + operation = temp_db.create() + operation.result(database_operation_timeout) + + databases_to_delete.append(temp_db) + def long_operation(transaction): + transaction.execute_sql("SELECT 1") + time.sleep(20) + transaction.execute_sql("SELECT 1") + with pytest.raises(Exception) as exc: + temp_db.run_in_transaction(long_operation) + assert exc.value.args[0] == "Transaction has been closed as it was running for more than 60 minutes" class FauxCall: def __init__(self, code, details="FauxCall"): diff --git a/tests/unit/test_batch.py b/tests/unit/test_batch.py index a7f4451379..b36ed44ce2 100644 --- a/tests/unit/test_batch.py +++ b/tests/unit/test_batch.py @@ -192,6 +192,14 @@ def test_commit_already_committed(self): self.assertNoSpans() + def test_commit_should_throw_error_for_recycled_session(self): + session = _Session() + batch = self._make_one(session) + batch._session = None + with self.assertRaises(Exception) as cm: + batch.commit() + self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + def test_commit_grpc_error(self): from google.api_core.exceptions import Unknown from google.cloud.spanner_v1.keyset import KeySet diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 72c612e4ec..54ff6a5435 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -137,29 +137,31 @@ def test_session_w_kwargs(self): self.assertEqual(checkout._kwargs, {"foo": "bar"}) @mock.patch('threading.Thread') - @mock.patch('google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC', 5) - @mock.patch('google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC', 10) def test_startCleaningLongRunningSessions_success(self, mock_thread_class): mock_thread = mock.MagicMock() mock_thread.start = mock.MagicMock() mock_thread_class.return_value = mock_thread pool = self._make_one() + pool._database = mock.MagicMock() pool._cleanup_task_ongoing_event.clear() - pool.startCleaningLongRunningSessions() - - # The event should be set, indicating the task is now ongoing - self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) - - # A new thread should have been created to start the task - threading.Thread.assert_called_once_with( - target=pool.deleteLongRunningTransactions, - args=(DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC), - daemon=True, - name='recycle-sessions' - ) - mock_thread.start.assert_called_once() - pool.stopCleaningLongRunningSessions() + with mock.patch('google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC', new=5), \ + mock.patch('google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC', new=10): + pool.startCleaningLongRunningSessions() + + # The event should be set, indicating the task is now ongoing + self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) + + # A new thread should have been created to start the task + threading.Thread.assert_called_once_with( + target=pool.deleteLongRunningTransactions, + args=(5, 10), + daemon=True, + name='recycle-sessions' + ) + mock_thread.start.assert_called_once() + pool.stopCleaningLongRunningSessions() + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) def test_stopCleaningLongRunningSessions(self): pool = self._make_one() @@ -249,6 +251,21 @@ def test_deleteLongRunningTransactions_deleteSession(self): self.assertFalse(session.transaction_logged) self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + def test_deleteLongRunningTransactions_close_if_no_transaction_is_released(self): + pool = self._setup_session_leak(False, True) + # Create a session that needs to be closed + session = mock.MagicMock() + session.transaction_logged = True + session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) + session.long_running = False + pool._borrowed_sessions = [session] + pool._cleanup_task_ongoing_event.set() + # Call deleteLongRunningTransactions + pool.deleteLongRunningTransactions(2, 2) + + # Assert that background task was closed as there was no transaction to close. + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + class TestFixedSizePool(unittest.TestCase): def _getTargetClass(self): @@ -315,6 +332,8 @@ def test_get_non_expired(self): self.assertIs(session, SESSIONS[i]) self.assertTrue(session._exists_checked) self.assertFalse(pool._sessions.full()) + #Stop Long running session + pool.stopCleaningLongRunningSessions() def test_get_expired(self): pool = self._make_one(size=4) @@ -330,8 +349,9 @@ def test_get_expired(self): session.create.assert_called() self.assertTrue(SESSIONS[0]._exists_checked) self.assertFalse(pool._sessions.full()) + pool.stopCleaningLongRunningSessions() - def test_get_longrunning_defaults(self): + def test_get_trigger_longrunning_and_set_defaults(self): pool = self._make_one(size=2) database = _Database("name") SESSIONS = [_Session(database)] * 3 @@ -474,7 +494,7 @@ def test_get_empty(self): session.create.assert_called() self.assertTrue(pool._sessions.empty()) - def test_get_longrunning_defaults(self): + def test_get_trigger_longrunning_and_set_defaults(self): pool = self._make_one(target_size=2) database = _Database("name") SESSIONS = [_Session(database)] * 3 @@ -645,7 +665,7 @@ def test_get_hit_no_ping(self): self.assertFalse(session._exists_checked) self.assertFalse(pool._sessions.full()) - def test_get_longrunning_defaults(self): + def test_get_trigger_longrunning_and_set_defaults(self): pool = self._make_one(size=2) database = _Database("name") SESSIONS = [_Session(database)] * 3 @@ -1162,6 +1182,9 @@ def __init__(self, name): self._route_to_leader_enabled = True self.close_inactive_transactions = True self.logging_enabled = True + self._logger = mock.MagicMock() + self._logger.info = mock.MagicMock() + self._logger.warn = mock.MagicMock() def mock_batch_create_sessions( request=None, @@ -1199,6 +1222,10 @@ def database_role(self): :returns: an str with the name of the database role. """ return self._database_role + + @property + def logger(self): + return self._logger def session(self, **kwargs): # always return first session in the list diff --git a/tests/unit/test_snapshot.py b/tests/unit/test_snapshot.py index 285328387c..a05ecc3715 100644 --- a/tests/unit/test_snapshot.py +++ b/tests/unit/test_snapshot.py @@ -815,6 +815,17 @@ def test_execute_sql_other_error(self): attributes=dict(BASE_ATTRIBUTES, **{"db.statement": SQL_QUERY}), ) + def test_execute_sql_should_throw_error_for_recycled_session(self): + session = _Session() + derived = self._makeDerived(session) + derived._session = None + + with self.assertRaises(Exception) as cm: + list(derived.execute_sql(SQL_QUERY)) + + self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + + def test_execute_sql_w_params_wo_param_types(self): database = _Database() session = _Session(database) @@ -1154,6 +1165,18 @@ def test_partition_read_other_error(self): BASE_ATTRIBUTES, table_id=TABLE_NAME, columns=tuple(COLUMNS) ), ) + + def test_partition_read_should_throw_error_for_recycled_session(self): + from google.cloud.spanner_v1.keyset import KeySet + keyset = KeySet(all_=True) + session = _Session() + derived = self._makeDerived(session) + derived._session = None + + with self.assertRaises(Exception) as cm: + list(derived.partition_read(TABLE_NAME, COLUMNS, keyset)) + + self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") def test_partition_read_w_retry(self): from google.cloud.spanner_v1.keyset import KeySet @@ -1314,6 +1337,16 @@ def test_partition_query_other_error(self): attributes=dict(BASE_ATTRIBUTES, **{"db.statement": SQL_QUERY}), ) + def test_partition_query_should_throw_error_for_recycled_session(self): + session = _Session() + derived = self._makeDerived(session) + derived._session = None + + with self.assertRaises(Exception) as cm: + list(derived.partition_query(SQL_QUERY)) + + self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + def test_partition_query_w_params_wo_param_types(self): database = _Database() session = _Session(database) diff --git a/tests/unit/test_transaction.py b/tests/unit/test_transaction.py index 4eb42027f7..857ea2c8a4 100644 --- a/tests/unit/test_transaction.py +++ b/tests/unit/test_transaction.py @@ -306,6 +306,14 @@ def test_commit_not_begun(self): self.assertNoSpans() + def test_commit_should_throw_error_for_recycled_session(self): + session = _Session() + transaction = self._make_one(session) + transaction._session = None + with self.assertRaises(Exception) as cm: + transaction.commit() + self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + def test_commit_already_committed(self): session = _Session() transaction = self._make_one(session) @@ -667,6 +675,14 @@ def test_batch_update_other_error(self): with self.assertRaises(RuntimeError): transaction.batch_update(statements=[DML_QUERY]) + def test_batch_update_should_throw_error_for_recycled_session(self): + session = _Session() + transaction = self._make_one(session) + transaction._session = None + with self.assertRaises(Exception) as cm: + transaction.batch_update(statements=[DML_QUERY]) + self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + def _batch_update_helper(self, error_after=None, count=0, request_options=None): from google.rpc.status_pb2 import Status from google.protobuf.struct_pb2 import Struct From 54e1717dff17771ad5e3d2e952b557e639e616dc Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Thu, 15 Jun 2023 16:19:44 +0530 Subject: [PATCH 07/24] session traces --- google/cloud/spanner_v1/pool.py | 35 +++++++++++++++------ tests/unit/spanner_dbapi/test_connection.py | 2 ++ tests/unit/test_pool.py | 11 +++++++ 3 files changed, 39 insertions(+), 9 deletions(-) diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index d3e93451d1..2b94cb5efc 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -17,7 +17,7 @@ import datetime import queue import threading -import random +import traceback import time from google.cloud.exceptions import NotFound from google.cloud.spanner_v1 import BatchCreateSessionsRequest @@ -27,7 +27,7 @@ _metadata_with_leader_aware_routing, ) from warnings import warn -import logging +from typing import List _NOW = datetime.datetime.utcnow # unit tests may replace @@ -45,6 +45,7 @@ class AbstractSessionPool(object): _database = None _sessions = None _borrowed_sessions = [] + _traces = {} _cleanup_task_ongoing_event = threading.Event() _cleanup_task_ongoing = False @@ -136,6 +137,10 @@ def _new_session(self): labels=self.labels, database_role=self.database_role ) + def _format_trace(self, frames: List[traceback.FrameSummary]) -> str: + stack = [f"\n at {frame.name} ({frame.filename}:{frame.line}:{frame.lineno})" for frame in frames] + return "".join(stack) + def session(self, **kwargs): """Check out a session from the pool. @@ -156,7 +161,7 @@ def startCleaningLongRunningSessions(self): if not AbstractSessionPool._cleanup_task_ongoing_event.is_set() and not AbstractSessionPool._cleanup_task_ongoing: AbstractSessionPool._cleanup_task_ongoing_event.set() if self._database.logging_enabled: - self._database.logger.info('95%% of the session pool is exhausted') + self._database.logger.info('95% of the session pool is exhausted') background = threading.Thread(target=self.deleteLongRunningTransactions, args=(DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC,), daemon=True, name='recycle-sessions') background.start() @@ -176,12 +181,12 @@ def deleteLongRunningTransactions(self, interval_sec, timeout_sec): start = time.time() sessions_to_delete = list(filter(lambda session : (datetime.datetime.utcnow() - session.checkout_time > datetime.timedelta(seconds=timeout_sec)) and not session.long_running, self._borrowed_sessions)) - for session in sessions_to_delete: + session_trace = self._format_trace(self._traces[session._session_id]) if self._database.close_inactive_transactions: if self._database.logging_enabled: self._database.logger.warn('Long running transaction! Transaction has been closed as it was running for ' + - 'more than 60 minutes. For long running transactions use batch or partitioned transactions.') + 'more than 60 minutes. For long running transactions use batch or partitioned transactions. ' + session_trace) if session._transaction is not None: session._transaction._session = None if session._batch is not None: @@ -193,7 +198,7 @@ def deleteLongRunningTransactions(self, interval_sec, timeout_sec): elif self._database.logging_enabled: if not session.transaction_logged: self._database.logger.warn('Transaction has been running for longer than 60 minutes and might be causing a leak. ' + - 'Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions.') + 'Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions. ' + session_trace) session.transaction_logged = True elapsed_time = time.time() - start @@ -247,6 +252,7 @@ def __init__( self.default_timeout = default_timeout self._sessions = queue.LifoQueue(size) self._borrowed_sessions = [] + self._traces = {} def bind(self, database): """Associate the pool with a database. @@ -302,11 +308,12 @@ def get(self, isLongRunning=False, timeout=None): session.long_running = isLongRunning session.transaction_logged = False self._borrowed_sessions.append(session) + self._traces[session._session_id] = traceback.extract_stack() if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : self.startCleaningLongRunningSessions() if self._database.logging_enabled and len(self._borrowed_sessions)/self.size == 1: - self._database.logger.warn('100%% of the session pool is exhausted') + self._database.logger.warn('100% of the session pool is exhausted') return session def put(self, session): @@ -322,6 +329,7 @@ def put(self, session): if self._borrowed_sessions.__contains__(session): self._borrowed_sessions.remove(session) self._sessions.put_nowait(session) + self._traces.pop(session._session_id, None) if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size < 0.95 : self.stopCleaningLongRunningSessions() @@ -367,6 +375,7 @@ def __init__(self, target_size=10, labels=None, database_role=None): self._database = None self._sessions = queue.LifoQueue(target_size) self._borrowed_sessions = [] + self._traces = {} def bind(self, database): """Associate the pool with a database. @@ -398,10 +407,12 @@ def get(self, isLongRunning=False): session.long_running = isLongRunning session.transaction_logged = False self._borrowed_sessions.append(session) + self._traces[session._session_id] = traceback.extract_stack() + if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.target_size >= 0.95 : self.startCleaningLongRunningSessions() if self._database.logging_enabled and len(self._borrowed_sessions)/self.target_size == 1: - self._database.logger.warn('100%% of the session pool is exhausted') + self._database.logger.warn('100% of the session pool is exhausted') return session def put(self, session): @@ -417,6 +428,7 @@ def put(self, session): if self._borrowed_sessions.__contains__(session): self._borrowed_sessions.remove(session) self._sessions.put_nowait(session) + self._traces.pop(session._session_id, None) if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.target_size < 0.95 : self.stopCleaningLongRunningSessions() except queue.Full: @@ -489,6 +501,7 @@ def __init__( self._delta = datetime.timedelta(seconds=ping_interval) self._sessions = queue.PriorityQueue(size) self._borrowed_sessions = [] + self._traces = {} def bind(self, database): """Associate the pool with a database. @@ -552,10 +565,11 @@ def get(self, isLongRunning=False, timeout=None): session.long_running = isLongRunning session.transaction_logged = False self._borrowed_sessions.append(session) + self._traces[session._session_id] = traceback.extract_stack() if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : self.startCleaningLongRunningSessions() if self._database.logging_enabled and len(self._borrowed_sessions)/self.size == 1: - self._database.logger.warn('100%% of the session pool is exhausted') + self._database.logger.warn('100% of the session pool is exhausted') return session def put(self, session): @@ -571,6 +585,7 @@ def put(self, session): if self._borrowed_sessions.__contains__(session): self._borrowed_sessions.remove(session) self._sessions.put_nowait((_NOW() + self._delta, session)) + self._traces.pop(session._session_id, None) if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size < 0.95 : self.stopCleaningLongRunningSessions() @@ -658,6 +673,7 @@ def __init__( ) self._pending_sessions = queue.Queue() self._borrowed_sessions = [] + self._traces = {} super(TransactionPingingPool, self).__init__( size, @@ -699,6 +715,7 @@ def put(self, session): if self._borrowed_sessions.__contains__(session): self._borrowed_sessions.remove(session) self._pending_sessions.put(session) + self._traces.pop(session._session_id, None) if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size < 0.95 : self.stopCleaningLongRunningSessions() else: diff --git a/tests/unit/spanner_dbapi/test_connection.py b/tests/unit/spanner_dbapi/test_connection.py index 54bb455e46..70cf7664b1 100644 --- a/tests/unit/spanner_dbapi/test_connection.py +++ b/tests/unit/spanner_dbapi/test_connection.py @@ -470,6 +470,7 @@ def test_commit_clears_statements(self, mock_transaction): """ connection = self._make_connection() connection._transaction = mock.Mock(rolled_back=False, committed=False) + connection._session = mock.MagicMock() connection._statements = [{}, {}] self.assertEqual(len(connection._statements), 2) @@ -486,6 +487,7 @@ def test_rollback_clears_statements(self, mock_transaction): """ connection = self._make_connection() connection._transaction = mock.Mock() + connection._session = mock.MagicMock() connection._statements = [{}, {}] self.assertEqual(len(connection._statements), 2) diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 54ff6a5435..06951c5309 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -15,6 +15,8 @@ from functools import total_ordering import unittest +import random +import string from time import sleep import threading import mock @@ -205,6 +207,8 @@ def test_deleteLongRunningTransactions_deleteAndLogSession(self): session.transaction_logged = False session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) session.long_running = False + session._session_id = 'session_id' + pool._traces['session_id'] = 'trace' pool._borrowed_sessions = [session] pool._cleanup_task_ongoing_event.set() # Call deleteLongRunningTransactions @@ -222,6 +226,8 @@ def test_deleteLongRunningTransactions_logSession(self): session.transaction_logged = False session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) session.long_running = False + session._session_id = 'session_id' + pool._traces['session_id'] = 'trace' pool._borrowed_sessions = [session] pool._cleanup_task_ongoing_event.set() # Call deleteLongRunningTransactions @@ -240,6 +246,8 @@ def test_deleteLongRunningTransactions_deleteSession(self): session.transaction_logged = False session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) session.long_running = False + session._session_id = 'session_id' + pool._traces['session_id'] = 'trace' pool._borrowed_sessions = [session] pool._cleanup_task_ongoing_event.set() # Call deleteLongRunningTransactions @@ -258,6 +266,8 @@ def test_deleteLongRunningTransactions_close_if_no_transaction_is_released(self) session.transaction_logged = True session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) session.long_running = False + session._session_id = 'session_id' + pool._traces['session_id'] = 'trace' pool._borrowed_sessions = [session] pool._cleanup_task_ongoing_event.set() # Call deleteLongRunningTransactions @@ -1146,6 +1156,7 @@ def __init__(self, database, exists=True, transaction=None): self.create = mock.Mock() self._deleted = False self._transaction = transaction + self._session_id = ''.join(random.choices(string.ascii_letters, k=10)) def __lt__(self, other): return id(self) < id(other) From 7ed07c666e4d908152467b58fd3c8cdf5f0e997d Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Thu, 15 Jun 2023 17:54:50 +0530 Subject: [PATCH 08/24] tests cases --- tests/unit/test_pool.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 06951c5309..f0fd2ecb7d 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -189,6 +189,7 @@ def put_side_effect(*args, **kwargs): pool._database.close_inactive_transactions = close_inactive_transactions pool._borrowed_sessions = [] pool._database.logger.warn = mock.MagicMock() + pool._format_trace = mock.MagicMock() return pool def test_deleteLongRunningTransactions_noSessionsToDelete(self): From 57309de43be6e4d44e1dbe7e51238cb9b45d40e1 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Thu, 15 Jun 2023 18:07:26 +0530 Subject: [PATCH 09/24] formatting --- google/cloud/spanner_dbapi/connection.py | 10 +- google/cloud/spanner_v1/batch.py | 4 +- google/cloud/spanner_v1/database.py | 4 +- google/cloud/spanner_v1/pool.py | 133 ++++++++++++++------ google/cloud/spanner_v1/session.py | 8 +- google/cloud/spanner_v1/snapshot.py | 10 +- google/cloud/spanner_v1/transaction.py | 6 +- tests/system/test_session_api.py | 23 +++- tests/unit/spanner_dbapi/test_connect.py | 14 ++- tests/unit/spanner_dbapi/test_connection.py | 20 ++- tests/unit/test_batch.py | 5 +- tests/unit/test_database.py | 10 +- tests/unit/test_pool.py | 78 +++++++----- tests/unit/test_snapshot.py | 23 ++-- tests/unit/test_transaction.py | 10 +- 15 files changed, 250 insertions(+), 108 deletions(-) diff --git a/google/cloud/spanner_dbapi/connection.py b/google/cloud/spanner_dbapi/connection.py index 681d6a0a6c..d30a1f806e 100644 --- a/google/cloud/spanner_dbapi/connection.py +++ b/google/cloud/spanner_dbapi/connection.py @@ -583,7 +583,15 @@ def connect( instance = client.instance(instance_id) conn = Connection( - instance, instance.database(database_id, pool=pool, logging_enabled=False, close_inactive_transactions=False) if database_id else None + instance, + instance.database( + database_id, + pool=pool, + logging_enabled=False, + close_inactive_transactions=False, + ) + if database_id + else None, ) if pool is not None: conn._own_pool = False diff --git a/google/cloud/spanner_v1/batch.py b/google/cloud/spanner_v1/batch.py index 400414f706..dfd926ab4b 100644 --- a/google/cloud/spanner_v1/batch.py +++ b/google/cloud/spanner_v1/batch.py @@ -145,7 +145,9 @@ def _check_state(self): if self.committed is not None: raise ValueError("Batch already committed") if self._session is None: - raise ValueError("Transaction has been closed as it was running for more than 60 minutes") + raise ValueError( + "Transaction has been closed as it was running for more than 60 minutes" + ) def commit(self, return_commit_stats=False, request_options=None): """Commit mutations to the database. diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index d2af6717f0..5f7753fb81 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -342,7 +342,7 @@ def database_role(self): :returns: a str with the name of the database role. """ return self._database_role - + @property def logging_enabled(self): """Test if logging is enabled. Default: False. @@ -400,7 +400,7 @@ def close_inactive_transactions(self): :returns: True if closing inactive transactions is enabled, else False. """ return self._close_inactive_transactions - + @property def spanner_api(self): """Helper for session-related API calls.""" diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index 2b94cb5efc..ff58cf9ee7 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -31,6 +31,7 @@ _NOW = datetime.datetime.utcnow # unit tests may replace + class AbstractSessionPool(object): """Specifies required API for concrete session pool implementations. @@ -46,7 +47,7 @@ class AbstractSessionPool(object): _sessions = None _borrowed_sessions = [] _traces = {} - + _cleanup_task_ongoing_event = threading.Event() _cleanup_task_ongoing = False @@ -92,7 +93,7 @@ def get(self, isLongRunning=False): """Check a session out from the pool. :type isLongRunning: bool - :param isLongRunning: Specifies if the session fetched is for long running transaction or not. + :param isLongRunning: Specifies if the session fetched is for long running transaction or not. Concrete implementations of this method are allowed to raise an error to signal that the pool is exhausted, or to block until a @@ -138,7 +139,10 @@ def _new_session(self): ) def _format_trace(self, frames: List[traceback.FrameSummary]) -> str: - stack = [f"\n at {frame.name} ({frame.filename}:{frame.line}:{frame.lineno})" for frame in frames] + stack = [ + f"\n at {frame.name} ({frame.filename}:{frame.line}:{frame.lineno})" + for frame in frames + ] return "".join(stack) def session(self, **kwargs): @@ -156,13 +160,25 @@ def session(self, **kwargs): def startCleaningLongRunningSessions(self): from google.cloud.spanner_v1._helpers import ( DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, - DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC + DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC, ) - if not AbstractSessionPool._cleanup_task_ongoing_event.is_set() and not AbstractSessionPool._cleanup_task_ongoing: + + if ( + not AbstractSessionPool._cleanup_task_ongoing_event.is_set() + and not AbstractSessionPool._cleanup_task_ongoing + ): AbstractSessionPool._cleanup_task_ongoing_event.set() if self._database.logging_enabled: - self._database.logger.info('95% of the session pool is exhausted') - background = threading.Thread(target=self.deleteLongRunningTransactions, args=(DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC,), daemon=True, name='recycle-sessions') + self._database.logger.info("95% of the session pool is exhausted") + background = threading.Thread( + target=self.deleteLongRunningTransactions, + args=( + DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, + DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC, + ), + daemon=True, + name="recycle-sessions", + ) background.start() def stopCleaningLongRunningSessions(self): @@ -173,20 +189,34 @@ def deleteLongRunningTransactions(self, interval_sec, timeout_sec): long_running_transaction_timer = time.time() transactions_closed = 0 while AbstractSessionPool._cleanup_task_ongoing_event.is_set(): - is_timeout_reached_and_no_transaction_closed = (time.time() - long_running_transaction_timer >= timeout_sec + interval_sec) and transactions_closed == 0 + is_timeout_reached_and_no_transaction_closed = ( + time.time() - long_running_transaction_timer + >= timeout_sec + interval_sec + ) and transactions_closed == 0 if is_timeout_reached_and_no_transaction_closed: break - + AbstractSessionPool._cleanup_task_ongoing = True start = time.time() - sessions_to_delete = list(filter(lambda session : (datetime.datetime.utcnow() - session.checkout_time > datetime.timedelta(seconds=timeout_sec)) - and not session.long_running, self._borrowed_sessions)) + sessions_to_delete = list( + filter( + lambda session: ( + datetime.datetime.utcnow() - session.checkout_time + > datetime.timedelta(seconds=timeout_sec) + ) + and not session.long_running, + self._borrowed_sessions, + ) + ) for session in sessions_to_delete: session_trace = self._format_trace(self._traces[session._session_id]) if self._database.close_inactive_transactions: if self._database.logging_enabled: - self._database.logger.warn('Long running transaction! Transaction has been closed as it was running for ' + - 'more than 60 minutes. For long running transactions use batch or partitioned transactions. ' + session_trace) + self._database.logger.warn( + "Long running transaction! Transaction has been closed as it was running for " + + "more than 60 minutes. For long running transactions use batch or partitioned transactions. " + + session_trace + ) if session._transaction is not None: session._transaction._session = None if session._batch is not None: @@ -197,16 +227,20 @@ def deleteLongRunningTransactions(self, interval_sec, timeout_sec): self.put(session) elif self._database.logging_enabled: if not session.transaction_logged: - self._database.logger.warn('Transaction has been running for longer than 60 minutes and might be causing a leak. ' + - 'Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions. ' + session_trace) - session.transaction_logged = True - + self._database.logger.warn( + "Transaction has been running for longer than 60 minutes and might be causing a leak. " + + "Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions. " + + session_trace + ) + session.transaction_logged = True + elapsed_time = time.time() - start if interval_sec - elapsed_time > 0: time.sleep(interval_sec - elapsed_time) AbstractSessionPool._cleanup_task_ongoing = False AbstractSessionPool._cleanup_task_ongoing_event.clear() + class FixedSizePool(AbstractSessionPool): """Concrete session pool implementation: @@ -253,6 +287,7 @@ def __init__( self._sessions = queue.LifoQueue(size) self._borrowed_sessions = [] self._traces = {} + def bind(self, database): """Associate the pool with a database. @@ -309,11 +344,16 @@ def get(self, isLongRunning=False, timeout=None): session.transaction_logged = False self._borrowed_sessions.append(session) self._traces[session._session_id] = traceback.extract_stack() - if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : + if ( + self._database.close_inactive_transactions or self._database.logging_enabled + ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() - - if self._database.logging_enabled and len(self._borrowed_sessions)/self.size == 1: - self._database.logger.warn('100% of the session pool is exhausted') + + if ( + self._database.logging_enabled + and len(self._borrowed_sessions) / self.size == 1 + ): + self._database.logger.warn("100% of the session pool is exhausted") return session def put(self, session): @@ -327,11 +367,13 @@ def put(self, session): :raises: :exc:`queue.Full` if the queue is full. """ if self._borrowed_sessions.__contains__(session): - self._borrowed_sessions.remove(session) + self._borrowed_sessions.remove(session) self._sessions.put_nowait(session) self._traces.pop(session._session_id, None) - - if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size < 0.95 : + + if ( + self._database.close_inactive_transactions or self._database.logging_enabled + ) and len(self._borrowed_sessions) / self.size < 0.95: self.stopCleaningLongRunningSessions() def clear(self): @@ -409,10 +451,15 @@ def get(self, isLongRunning=False): self._borrowed_sessions.append(session) self._traces[session._session_id] = traceback.extract_stack() - if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.target_size >= 0.95 : + if ( + self._database.close_inactive_transactions or self._database.logging_enabled + ) and len(self._borrowed_sessions) / self.target_size >= 0.95: self.startCleaningLongRunningSessions() - if self._database.logging_enabled and len(self._borrowed_sessions)/self.target_size == 1: - self._database.logger.warn('100% of the session pool is exhausted') + if ( + self._database.logging_enabled + and len(self._borrowed_sessions) / self.target_size == 1 + ): + self._database.logger.warn("100% of the session pool is exhausted") return session def put(self, session): @@ -429,7 +476,10 @@ def put(self, session): self._borrowed_sessions.remove(session) self._sessions.put_nowait(session) self._traces.pop(session._session_id, None) - if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.target_size < 0.95 : + if ( + self._database.close_inactive_transactions + or self._database.logging_enabled + ) and len(self._borrowed_sessions) / self.target_size < 0.95: self.stopCleaningLongRunningSessions() except queue.Full: try: @@ -566,10 +616,15 @@ def get(self, isLongRunning=False, timeout=None): session.transaction_logged = False self._borrowed_sessions.append(session) self._traces[session._session_id] = traceback.extract_stack() - if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size >= 0.95 : + if ( + self._database.close_inactive_transactions or self._database.logging_enabled + ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() - if self._database.logging_enabled and len(self._borrowed_sessions)/self.size == 1: - self._database.logger.warn('100% of the session pool is exhausted') + if ( + self._database.logging_enabled + and len(self._borrowed_sessions) / self.size == 1 + ): + self._database.logger.warn("100% of the session pool is exhausted") return session def put(self, session): @@ -583,10 +638,12 @@ def put(self, session): :raises: :exc:`queue.Full` if the queue is full. """ if self._borrowed_sessions.__contains__(session): - self._borrowed_sessions.remove(session) + self._borrowed_sessions.remove(session) self._sessions.put_nowait((_NOW() + self._delta, session)) self._traces.pop(session._session_id, None) - if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size < 0.95 : + if ( + self._database.close_inactive_transactions or self._database.logging_enabled + ) and len(self._borrowed_sessions) / self.size < 0.95: self.stopCleaningLongRunningSessions() def clear(self): @@ -716,7 +773,10 @@ def put(self, session): self._borrowed_sessions.remove(session) self._pending_sessions.put(session) self._traces.pop(session._session_id, None) - if (self._database.close_inactive_transactions or self._database.logging_enabled) and len(self._borrowed_sessions)/self.size < 0.95 : + if ( + self._database.close_inactive_transactions + or self._database.logging_enabled + ) and len(self._borrowed_sessions) / self.size < 0.95: self.stopCleaningLongRunningSessions() else: super(TransactionPingingPool, self).put(session) @@ -749,5 +809,8 @@ def __enter__(self): return self._session def __exit__(self, *ignored): - if not (self._session._transaction is not None and self._session._transaction._session is None): + if not ( + self._session._transaction is not None + and self._session._transaction._session is None + ): self._pool.put(self._session) diff --git a/google/cloud/spanner_v1/session.py b/google/cloud/spanner_v1/session.py index 19ccddea92..dfb8c0d4fc 100644 --- a/google/cloud/spanner_v1/session.py +++ b/google/cloud/spanner_v1/session.py @@ -96,7 +96,7 @@ def labels(self): :returns: the labels dict (empty if no labels were assigned. """ return self._labels - + @property def checkout_time(self): """Get Check out time for session @@ -104,7 +104,7 @@ def checkout_time(self): :returns: the checkedout time for a session if assigned. """ return self._checkout_time - + @checkout_time.setter def checkout_time(self, value): """Set Check out time for session @@ -120,7 +120,7 @@ def long_running(self): :returns: True if session is long running, else False. """ return self._long_running - + @long_running.setter def long_running(self, value): """Sets if the session is used for long running transaction. @@ -136,7 +136,7 @@ def transaction_logged(self): :returns: True if session is already logged for long running, else False. """ return self._transaction_logged - + @transaction_logged.setter def transaction_logged(self, value): """Sets if the session is already logged for long running transaction. diff --git a/google/cloud/spanner_v1/snapshot.py b/google/cloud/spanner_v1/snapshot.py index 16a77c6f3b..8f8160be8c 100644 --- a/google/cloud/spanner_v1/snapshot.py +++ b/google/cloud/spanner_v1/snapshot.py @@ -154,7 +154,9 @@ class _SnapshotBase(_SessionWrapper): def _check_session_state(self): if self._session is None: - raise ValueError("Transaction has been closed as it was running for more than 60 minutes") + raise ValueError( + "Transaction has been closed as it was running for more than 60 minutes" + ) def _make_txn_selector(self): """Helper for :meth:`read` / :meth:`execute_sql`. @@ -235,9 +237,9 @@ def read( for reuse of single-use snapshots, or if a transaction ID is already pending for multiple-use snapshots. """ - + self._check_session_state() - + if self._read_request_count > 0: if not self._multi_use: raise ValueError("Cannot re-use single-use snapshot.") @@ -803,7 +805,7 @@ def begin(self): if self._read_request_count > 0: raise ValueError("Read-only transaction already pending") - + self._check_session_state() database = self._session._database diff --git a/google/cloud/spanner_v1/transaction.py b/google/cloud/spanner_v1/transaction.py index 22a66a4d67..de0b40f2f2 100644 --- a/google/cloud/spanner_v1/transaction.py +++ b/google/cloud/spanner_v1/transaction.py @@ -64,8 +64,10 @@ def __init__(self, session): def _check_session_state(self): if self._session is None: - raise ValueError("Transaction has been closed as it was running for more than 60 minutes") - + raise ValueError( + "Transaction has been closed as it was running for more than 60 minutes" + ) + def _check_state(self): """Helper for :meth:`commit` et al. diff --git a/tests/system/test_session_api.py b/tests/system/test_session_api.py index d0d4d0846f..c97b801017 100644 --- a/tests/system/test_session_api.py +++ b/tests/system/test_session_api.py @@ -2516,31 +2516,44 @@ def test_partition_query(sessions_database, not_emulator): assert union == all_data_rows batch_txn.close() -def test_should_close_inactive_transactions(not_emulator, not_postgres, shared_instance, database_operation_timeout, databases_to_delete): + +def test_should_close_inactive_transactions( + not_emulator, + not_postgres, + shared_instance, + database_operation_timeout, + databases_to_delete, +): spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC = 2 spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC = 5 database_name = _helpers.unique_id("test_longrunning", separator="_") pool = spanner_v1.BurstyPool(target_size=1) - + temp_db = shared_instance.database( database_name, ddl_statements=_helpers.DDL_STATEMENTS, pool=pool, close_inactive_transactions=True, - logging_enabled=True + logging_enabled=True, ) operation = temp_db.create() operation.result(database_operation_timeout) - + databases_to_delete.append(temp_db) + def long_operation(transaction): transaction.execute_sql("SELECT 1") time.sleep(20) transaction.execute_sql("SELECT 1") + with pytest.raises(Exception) as exc: temp_db.run_in_transaction(long_operation) - assert exc.value.args[0] == "Transaction has been closed as it was running for more than 60 minutes" + assert ( + exc.value.args[0] + == "Transaction has been closed as it was running for more than 60 minutes" + ) + class FauxCall: def __init__(self, code, details="FauxCall"): diff --git a/tests/unit/spanner_dbapi/test_connect.py b/tests/unit/spanner_dbapi/test_connect.py index cfb73ea820..a847562926 100644 --- a/tests/unit/spanner_dbapi/test_connect.py +++ b/tests/unit/spanner_dbapi/test_connect.py @@ -53,7 +53,12 @@ def test_w_implicit(self, mock_client): client.instance.assert_called_once_with(INSTANCE) self.assertIs(connection.database, database) - instance.database.assert_called_once_with(DATABASE, pool=None, logging_enabled=False, close_inactive_transactions=False) + instance.database.assert_called_once_with( + DATABASE, + pool=None, + logging_enabled=False, + close_inactive_transactions=False, + ) # Datbase constructs its own pool self.assertIsNotNone(connection.database._pool) self.assertTrue(connection.instance._client.route_to_leader_enabled) @@ -96,7 +101,12 @@ def test_w_explicit(self, mock_client): client.instance.assert_called_once_with(INSTANCE) self.assertIs(connection.database, database) - instance.database.assert_called_once_with(DATABASE, pool=pool, logging_enabled=False, close_inactive_transactions=False) + instance.database.assert_called_once_with( + DATABASE, + pool=pool, + logging_enabled=False, + close_inactive_transactions=False, + ) def test_w_credential_file_path(self, mock_client): from google.cloud.spanner_dbapi import connect diff --git a/tests/unit/spanner_dbapi/test_connection.py b/tests/unit/spanner_dbapi/test_connection.py index 70cf7664b1..fcddcd6864 100644 --- a/tests/unit/spanner_dbapi/test_connection.py +++ b/tests/unit/spanner_dbapi/test_connection.py @@ -1002,12 +1002,26 @@ def __init__(self, name="instance_id", client=None): self.name = name self._client = client - def database(self, database_id="database_id", pool=None, logging_enabled=False, close_inactive_transactions=False): - return _Database(database_id, pool, logging_enabled=False, close_inactive_transactions=False) + def database( + self, + database_id="database_id", + pool=None, + logging_enabled=False, + close_inactive_transactions=False, + ): + return _Database( + database_id, pool, logging_enabled=False, close_inactive_transactions=False + ) class _Database(object): - def __init__(self, database_id="database_id", pool=None, logging_enabled=False, close_inactive_transactions=False): + def __init__( + self, + database_id="database_id", + pool=None, + logging_enabled=False, + close_inactive_transactions=False, + ): self.name = database_id self.pool = pool self.logging_enabled = logging_enabled diff --git a/tests/unit/test_batch.py b/tests/unit/test_batch.py index b36ed44ce2..7a4c921d47 100644 --- a/tests/unit/test_batch.py +++ b/tests/unit/test_batch.py @@ -198,7 +198,10 @@ def test_commit_should_throw_error_for_recycled_session(self): batch._session = None with self.assertRaises(Exception) as cm: batch.commit() - self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + self.assertEqual( + str(cm.exception), + "Transaction has been closed as it was running for more than 60 minutes", + ) def test_commit_grpc_error(self): from google.api_core.exceptions import Unknown diff --git a/tests/unit/test_database.py b/tests/unit/test_database.py index 8356a56b9a..3961891480 100644 --- a/tests/unit/test_database.py +++ b/tests/unit/test_database.py @@ -151,18 +151,14 @@ def test_ctor_w_route_to_leader_disbled(self): def test_ctor_w_logger_enabled(self): instance = _Instance(self.INSTANCE_NAME) - database = self._make_one( - self.DATABASE_ID, instance, logging_enabled=True - ) + database = self._make_one(self.DATABASE_ID, instance, logging_enabled=True) self.assertEqual(database.database_id, self.DATABASE_ID) self.assertIs(database._instance, instance) self.assertIs(database.logging_enabled, True) def test_ctor_w_logger_disabled(self): instance = _Instance(self.INSTANCE_NAME) - database = self._make_one( - self.DATABASE_ID, instance, logging_enabled=False - ) + database = self._make_one(self.DATABASE_ID, instance, logging_enabled=False) self.assertEqual(database.database_id, self.DATABASE_ID) self.assertIs(database._instance, instance) self.assertIs(database.logging_enabled, False) @@ -1249,7 +1245,7 @@ def test_snapshot_longrunningvalue(self): database = self._make_one(self.DATABASE_ID, instance, pool=pool) with database.snapshot() as checkout: self.assertIsInstance(checkout, Snapshot) - + self.assertEqual(pool.get.call_count, 1) # get method of pool is passed without any param, that means longrunning param is false pool.get.assert_called_once_with() diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index f0fd2ecb7d..4635ec63c6 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -23,9 +23,10 @@ import datetime from google.cloud.spanner_v1._helpers import ( DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, - DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC + DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC, ) + def _make_database(name="name"): from google.cloud.spanner_v1.database import Database @@ -138,7 +139,7 @@ def test_session_w_kwargs(self): self.assertIsNone(checkout._session) self.assertEqual(checkout._kwargs, {"foo": "bar"}) - @mock.patch('threading.Thread') + @mock.patch("threading.Thread") def test_startCleaningLongRunningSessions_success(self, mock_thread_class): mock_thread = mock.MagicMock() mock_thread.start = mock.MagicMock() @@ -147,8 +148,13 @@ def test_startCleaningLongRunningSessions_success(self, mock_thread_class): pool = self._make_one() pool._database = mock.MagicMock() pool._cleanup_task_ongoing_event.clear() - with mock.patch('google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC', new=5), \ - mock.patch('google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC', new=10): + with mock.patch( + "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC", + new=5, + ), mock.patch( + "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC", + new=10, + ): pool.startCleaningLongRunningSessions() # The event should be set, indicating the task is now ongoing @@ -159,12 +165,12 @@ def test_startCleaningLongRunningSessions_success(self, mock_thread_class): target=pool.deleteLongRunningTransactions, args=(5, 10), daemon=True, - name='recycle-sessions' + name="recycle-sessions", ) mock_thread.start.assert_called_once() pool.stopCleaningLongRunningSessions() self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) - + def test_stopCleaningLongRunningSessions(self): pool = self._make_one() pool._cleanup_task_ongoing_event.set() @@ -172,12 +178,12 @@ def test_stopCleaningLongRunningSessions(self): # The event should not be set, indicating the task is now stopped self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) - - + def _setup_session_leak(self, close_inactive_transactions, logging_enabled): pool = self._make_one() pool._database = mock.MagicMock() pool.put = mock.MagicMock() + def put_side_effect(*args, **kwargs): pool._borrowed_sessions = [] pool._cleanup_task_ongoing_event.clear() @@ -206,10 +212,12 @@ def test_deleteLongRunningTransactions_deleteAndLogSession(self): # Create a session that needs to be closed session = mock.MagicMock() session.transaction_logged = False - session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) + session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta( + minutes=61 + ) session.long_running = False - session._session_id = 'session_id' - pool._traces['session_id'] = 'trace' + session._session_id = "session_id" + pool._traces["session_id"] = "trace" pool._borrowed_sessions = [session] pool._cleanup_task_ongoing_event.set() # Call deleteLongRunningTransactions @@ -225,10 +233,12 @@ def test_deleteLongRunningTransactions_logSession(self): # Create a session that needs to be closed session = mock.MagicMock() session.transaction_logged = False - session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) + session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta( + minutes=61 + ) session.long_running = False - session._session_id = 'session_id' - pool._traces['session_id'] = 'trace' + session._session_id = "session_id" + pool._traces["session_id"] = "trace" pool._borrowed_sessions = [session] pool._cleanup_task_ongoing_event.set() # Call deleteLongRunningTransactions @@ -245,10 +255,12 @@ def test_deleteLongRunningTransactions_deleteSession(self): # Create a session that needs to be closed session = mock.MagicMock() session.transaction_logged = False - session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) + session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta( + minutes=61 + ) session.long_running = False - session._session_id = 'session_id' - pool._traces['session_id'] = 'trace' + session._session_id = "session_id" + pool._traces["session_id"] = "trace" pool._borrowed_sessions = [session] pool._cleanup_task_ongoing_event.set() # Call deleteLongRunningTransactions @@ -265,10 +277,12 @@ def test_deleteLongRunningTransactions_close_if_no_transaction_is_released(self) # Create a session that needs to be closed session = mock.MagicMock() session.transaction_logged = True - session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta(minutes=61) + session.checkout_time = datetime.datetime.utcnow() - datetime.timedelta( + minutes=61 + ) session.long_running = False - session._session_id = 'session_id' - pool._traces['session_id'] = 'trace' + session._session_id = "session_id" + pool._traces["session_id"] = "trace" pool._borrowed_sessions = [session] pool._cleanup_task_ongoing_event.set() # Call deleteLongRunningTransactions @@ -343,7 +357,7 @@ def test_get_non_expired(self): self.assertIs(session, SESSIONS[i]) self.assertTrue(session._exists_checked) self.assertFalse(pool._sessions.full()) - #Stop Long running session + # Stop Long running session pool.stopCleaningLongRunningSessions() def test_get_expired(self): @@ -376,7 +390,7 @@ def test_get_trigger_longrunning_and_set_defaults(self): self.assertFalse(session.transaction_logged) self.assertIs(session, pool._borrowed_sessions[0]) self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) - + # Fetch new session which will trigger the cleanup task. session1 = pool.get() self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) @@ -433,7 +447,7 @@ def test_put_non_full(self): pool._cleanup_task_ongoing_event.set() pool.put(session) - + self.assertEqual(len(pool._borrowed_sessions), 0) self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) self.assertTrue(pool._sessions.full()) @@ -511,7 +525,7 @@ def test_get_trigger_longrunning_and_set_defaults(self): SESSIONS = [_Session(database)] * 3 database._sessions.extend(SESSIONS) pool.bind(database) - + session = pool.get() session.create.assert_called() self.assertIsInstance(session.checkout_time, datetime.datetime) @@ -519,7 +533,7 @@ def test_get_trigger_longrunning_and_set_defaults(self): self.assertFalse(session.transaction_logged) self.assertTrue(len(pool._borrowed_sessions), 1) self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) - + # Fetch new session which will trigger the cleanup task. session1 = pool.get() self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) @@ -688,7 +702,7 @@ def test_get_trigger_longrunning_and_set_defaults(self): self.assertFalse(session.transaction_logged) self.assertTrue(len(pool._borrowed_sessions), 1) self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) - + # Fetch new session which will trigger the cleanup task. session1 = pool.get() self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) @@ -696,7 +710,7 @@ def test_get_trigger_longrunning_and_set_defaults(self): # Stop the background task. pool.stopCleaningLongRunningSessions() self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) - + def test_get_hit_w_ping(self): import datetime from google.cloud._testing import _Monkey @@ -784,7 +798,7 @@ def test_put_non_full(self): pool = self._make_one(size=1) session_queue = pool._sessions = _Queue() - + now = datetime.datetime.utcnow() database = _Database("name") session = _Session(database) @@ -1005,14 +1019,14 @@ def test_put_non_full_w_active_txn(self): self.assertEqual(len(pending._items), 0) self.assertEqual(len(pool._borrowed_sessions), 0) self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) - + txn.begin.assert_not_called() def test_put_non_full_w_committed_txn(self): pool = self._make_one(size=1) session_queue = pool._sessions = _Queue() pending = pool._pending_sessions = _Queue() - + database = _Database("name") session = _Session(database) database._sessions.extend([session]) @@ -1157,7 +1171,7 @@ def __init__(self, database, exists=True, transaction=None): self.create = mock.Mock() self._deleted = False self._transaction = transaction - self._session_id = ''.join(random.choices(string.ascii_letters, k=10)) + self._session_id = "".join(random.choices(string.ascii_letters, k=10)) def __lt__(self, other): return id(self) < id(other) @@ -1234,7 +1248,7 @@ def database_role(self): :returns: an str with the name of the database role. """ return self._database_role - + @property def logger(self): return self._logger diff --git a/tests/unit/test_snapshot.py b/tests/unit/test_snapshot.py index a05ecc3715..c90b58725e 100644 --- a/tests/unit/test_snapshot.py +++ b/tests/unit/test_snapshot.py @@ -822,9 +822,11 @@ def test_execute_sql_should_throw_error_for_recycled_session(self): with self.assertRaises(Exception) as cm: list(derived.execute_sql(SQL_QUERY)) - - self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + self.assertEqual( + str(cm.exception), + "Transaction has been closed as it was running for more than 60 minutes", + ) def test_execute_sql_w_params_wo_param_types(self): database = _Database() @@ -1165,9 +1167,10 @@ def test_partition_read_other_error(self): BASE_ATTRIBUTES, table_id=TABLE_NAME, columns=tuple(COLUMNS) ), ) - + def test_partition_read_should_throw_error_for_recycled_session(self): from google.cloud.spanner_v1.keyset import KeySet + keyset = KeySet(all_=True) session = _Session() derived = self._makeDerived(session) @@ -1175,8 +1178,11 @@ def test_partition_read_should_throw_error_for_recycled_session(self): with self.assertRaises(Exception) as cm: list(derived.partition_read(TABLE_NAME, COLUMNS, keyset)) - - self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + + self.assertEqual( + str(cm.exception), + "Transaction has been closed as it was running for more than 60 minutes", + ) def test_partition_read_w_retry(self): from google.cloud.spanner_v1.keyset import KeySet @@ -1344,8 +1350,11 @@ def test_partition_query_should_throw_error_for_recycled_session(self): with self.assertRaises(Exception) as cm: list(derived.partition_query(SQL_QUERY)) - - self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + + self.assertEqual( + str(cm.exception), + "Transaction has been closed as it was running for more than 60 minutes", + ) def test_partition_query_w_params_wo_param_types(self): database = _Database() diff --git a/tests/unit/test_transaction.py b/tests/unit/test_transaction.py index 857ea2c8a4..2577431372 100644 --- a/tests/unit/test_transaction.py +++ b/tests/unit/test_transaction.py @@ -312,7 +312,10 @@ def test_commit_should_throw_error_for_recycled_session(self): transaction._session = None with self.assertRaises(Exception) as cm: transaction.commit() - self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + self.assertEqual( + str(cm.exception), + "Transaction has been closed as it was running for more than 60 minutes", + ) def test_commit_already_committed(self): session = _Session() @@ -681,7 +684,10 @@ def test_batch_update_should_throw_error_for_recycled_session(self): transaction._session = None with self.assertRaises(Exception) as cm: transaction.batch_update(statements=[DML_QUERY]) - self.assertEqual(str(cm.exception), "Transaction has been closed as it was running for more than 60 minutes") + self.assertEqual( + str(cm.exception), + "Transaction has been closed as it was running for more than 60 minutes", + ) def _batch_update_helper(self, error_after=None, count=0, request_options=None): from google.rpc.status_pb2 import Status From c38b15db12d3ac58586f86754bcd2619a6c534bc Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Thu, 15 Jun 2023 19:31:34 +0530 Subject: [PATCH 10/24] documentation --- google/cloud/spanner_v1/database.py | 13 ++- google/cloud/spanner_v1/instance.py | 8 ++ google/cloud/spanner_v1/pool.py | 141 +++++++++++++++++++--------- google/cloud/spanner_v1/session.py | 20 +--- 4 files changed, 120 insertions(+), 62 deletions(-) diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index 5f7753fb81..28da86f6f4 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -108,11 +108,20 @@ class Database(object): passed, the database will construct an instance of :class:`~google.cloud.spanner_v1.pool.BurstyPool`. + :type logging_enabled: boolean + :parama logging_enabled: (Optional) Represents whether the database + has logging enabled or not. Default is True + :type logger: :class:`logging.Logger` :param logger: (Optional) a custom logger that is used if `log_commit_stats` is `True` to log commit statistics. If not passed, a logger will be created when needed that will log the commit statistics to stdout. + + :type close_inactive_transactions: boolean + :param close_inactive_transactions: (Optional) Represents whether the database + has close inactive transactions enabled or not. Default is False + :type encryption_config: :class:`~google.cloud.spanner_admin_database_v1.types.EncryptionConfig` or :class:`~google.cloud.spanner_admin_database_v1.types.RestoreDatabaseEncryptionConfig` @@ -345,7 +354,7 @@ def database_role(self): @property def logging_enabled(self): - """Test if logging is enabled. Default: False. + """Whether the database has logging enabled. Default: True. :rtype: bool :returns: True if logging is enabled, else False. """ @@ -395,7 +404,7 @@ def logger(self): @property def close_inactive_transactions(self): - """Test if closing inactive transactions is enabled. Default: True. + """Whether the database has has closing inactive transactions enabled. Default: False. :rtype: bool :returns: True if closing inactive transactions is enabled, else False. """ diff --git a/google/cloud/spanner_v1/instance.py b/google/cloud/spanner_v1/instance.py index 3625ee0a88..0f090a2a96 100644 --- a/google/cloud/spanner_v1/instance.py +++ b/google/cloud/spanner_v1/instance.py @@ -449,12 +449,20 @@ def database( :class:`~google.cloud.spanner_v1.pool.AbstractSessionPool`. :param pool: (Optional) session pool to be used by database. + :type logging_enabled: boolean + :param logging_enabled: (Optional) Represents whether the database + has logging enabled or not. Default is True + :type logger: :class:`logging.Logger` :param logger: (Optional) a custom logger that is used if `log_commit_stats` is `True` to log commit statistics. If not passed, a logger will be created when needed that will log the commit statistics to stdout. + :type close_inactive_transactions: boolean + :param close_inactive_transactions: (Optional) Represents whether the database + has close inactive transactions enabled or not. Default is False + :type encryption_config: :class:`~google.cloud.spanner_admin_database_v1.types.EncryptionConfig` or :class:`~google.cloud.spanner_admin_database_v1.types.RestoreDatabaseEncryptionConfig` diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index ff58cf9ee7..0fe85a217f 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -139,6 +139,12 @@ def _new_session(self): ) def _format_trace(self, frames: List[traceback.FrameSummary]) -> str: + """Helper for formatting traceback frames into more readable trace. + :type frames: list[traceback.FrameSummary] + :param frames: list of stack frames + :rtype: str + :returns: fromatted trace. + """ stack = [ f"\n at {frame.name} ({frame.filename}:{frame.line}:{frame.lineno})" for frame in frames @@ -158,6 +164,7 @@ def session(self, **kwargs): return SessionCheckout(self, **kwargs) def startCleaningLongRunningSessions(self): + """Starts background task for recycling session.""" from google.cloud.spanner_v1._helpers import ( DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC, @@ -182,64 +189,87 @@ def startCleaningLongRunningSessions(self): background.start() def stopCleaningLongRunningSessions(self): + """Stops background task for recycling session.""" AbstractSessionPool._cleanup_task_ongoing_event.clear() AbstractSessionPool._cleanup_task_ongoing = False - def deleteLongRunningTransactions(self, interval_sec, timeout_sec): + def deleteLongRunningTransactions( + self, longRunningTransactionInterval_sec, longRunningTransactionTimeout_sec + ): + """Recycles sessions with long-running transactions + :param longRunningTransactionInterval_sec: Interval for running background task in seconds. + :param longRunningTransactionTimeout_sec: Timeout for recycling sessions in seconds. + """ long_running_transaction_timer = time.time() transactions_closed = 0 while AbstractSessionPool._cleanup_task_ongoing_event.is_set(): - is_timeout_reached_and_no_transaction_closed = ( + is_timeout_reached = ( time.time() - long_running_transaction_timer - >= timeout_sec + interval_sec - ) and transactions_closed == 0 - if is_timeout_reached_and_no_transaction_closed: + >= longRunningTransactionTimeout_sec + + longRunningTransactionInterval_sec + ) + + if is_timeout_reached and transactions_closed == 0: break AbstractSessionPool._cleanup_task_ongoing = True - start = time.time() - sessions_to_delete = list( - filter( - lambda session: ( - datetime.datetime.utcnow() - session.checkout_time - > datetime.timedelta(seconds=timeout_sec) - ) - and not session.long_running, - self._borrowed_sessions, - ) - ) + iteration_start = time.time() + + # Retrieve a list of sessions to delete + sessions_to_delete = [ + session + for session in self._borrowed_sessions + if (datetime.datetime.utcnow() - session.checkout_time) + > datetime.timedelta(seconds=longRunningTransactionTimeout_sec) + and not session.long_running + ] + for session in sessions_to_delete: - session_trace = self._format_trace(self._traces[session._session_id]) - if self._database.close_inactive_transactions: - if self._database.logging_enabled: - self._database.logger.warn( - "Long running transaction! Transaction has been closed as it was running for " - + "more than 60 minutes. For long running transactions use batch or partitioned transactions. " - + session_trace - ) - if session._transaction is not None: - session._transaction._session = None - if session._batch is not None: - session._batch._session = None - if session._snapshot is not None: - session._snapshpt._session = None - transactions_closed += 1 - self.put(session) - elif self._database.logging_enabled: - if not session.transaction_logged: - self._database.logger.warn( - "Transaction has been running for longer than 60 minutes and might be causing a leak. " - + "Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions. " - + session_trace - ) - session.transaction_logged = True - - elapsed_time = time.time() - start - if interval_sec - elapsed_time > 0: - time.sleep(interval_sec - elapsed_time) + self._recycle_session(session, transactions_closed) + + # Calculate and sleep for the time remaining until the next iteration based on the interval. + iteration_elapsed = time.time() - iteration_start + remaining_time = longRunningTransactionInterval_sec - iteration_elapsed + if remaining_time > 0: + time.sleep(remaining_time) + AbstractSessionPool._cleanup_task_ongoing = False AbstractSessionPool._cleanup_task_ongoing_event.clear() + def _recycle_session(self, session, transactions_closed): + """Helper method to recycle session for background task.""" + session_trace = self._format_trace(self._traces[session._session_id]) + if self._database.close_inactive_transactions: + if self._database.logging_enabled: + # Log a warning for a long-running transaction that has been closed + self._database.logger.warn( + "Long running transaction! Transaction has been closed as it was running for " + + "more than 60 minutes. For long running transactions use batch or partitioned transactions. " + + session_trace + ) + + # Set the session as None for associated objects (transaction, batch, snapshot) + if session._transaction is not None: + session._transaction._session = None + if session._batch is not None: + session._batch._session = None + if session._snapshot is not None: + session._snapshot._session = None + + # Increment the count of closed transactions and return the session to the pool + transactions_closed += 1 + self.put(session) + elif self._database.logging_enabled: + # Log a warning for a potentially leaking long-running transaction. + # Only log the warning if it hasn't been logged already. + if not session.transaction_logged: + self._database.logger.warn( + "Transaction has been running for longer than 60 minutes and might be causing a leak. " + + "Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions. " + + session_trace + ) + session.transaction_logged = True + class FixedSizePool(AbstractSessionPool): """Concrete session pool implementation: @@ -339,21 +369,26 @@ def get(self, isLongRunning=False, timeout=None): session = self._database.session() session.create() + # Set session properties. session.checkout_time = datetime.datetime.utcnow() session.long_running = isLongRunning session.transaction_logged = False self._borrowed_sessions.append(session) self._traces[session._session_id] = traceback.extract_stack() + + # Start background task for handling long-running transactions if 95% of sessions are checked out. if ( self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() + # Log a warning message if Session pool is exhausted. if ( self._database.logging_enabled and len(self._borrowed_sessions) / self.size == 1 ): self._database.logger.warn("100% of the session pool is exhausted") + return session def put(self, session): @@ -371,6 +406,7 @@ def put(self, session): self._sessions.put_nowait(session) self._traces.pop(session._session_id, None) + # Stop background task for handling long running transactions if less than 95% of sessions are checked out." if ( self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size < 0.95: @@ -445,21 +481,27 @@ def get(self, isLongRunning=False): if not session.exists(): session = self._new_session() session.create() + + # Set session properties. session.checkout_time = datetime.datetime.utcnow() session.long_running = isLongRunning session.transaction_logged = False self._borrowed_sessions.append(session) self._traces[session._session_id] = traceback.extract_stack() + # Start background task for handling long-running transactions if 95% of sessions are checked out. if ( self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.target_size >= 0.95: self.startCleaningLongRunningSessions() + + # Log a warning message if Session pool is exhausted. if ( self._database.logging_enabled and len(self._borrowed_sessions) / self.target_size == 1 ): self._database.logger.warn("100% of the session pool is exhausted") + return session def put(self, session): @@ -476,6 +518,8 @@ def put(self, session): self._borrowed_sessions.remove(session) self._sessions.put_nowait(session) self._traces.pop(session._session_id, None) + + # Stop background task for handling long running transactions if less than 95% of sessions are checked out." if ( self._database.close_inactive_transactions or self._database.logging_enabled @@ -611,15 +655,20 @@ def get(self, isLongRunning=False, timeout=None): session = self._new_session() session.create() + # Set session properties. session.checkout_time = datetime.datetime.utcnow() session.long_running = isLongRunning session.transaction_logged = False self._borrowed_sessions.append(session) self._traces[session._session_id] = traceback.extract_stack() + + # Start background task for handling long-running transactions if 95% of sessions are checked out. if ( self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() + + # Log a warning message if Session pool is exhausted. if ( self._database.logging_enabled and len(self._borrowed_sessions) / self.size == 1 @@ -641,6 +690,8 @@ def put(self, session): self._borrowed_sessions.remove(session) self._sessions.put_nowait((_NOW() + self._delta, session)) self._traces.pop(session._session_id, None) + + # Stop background task for handling long running transactions if less than 95% of sessions are checked out." if ( self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size < 0.95: @@ -773,6 +824,8 @@ def put(self, session): self._borrowed_sessions.remove(session) self._pending_sessions.put(session) self._traces.pop(session._session_id, None) + + # Stop background task for handling long running transactions if less than 95% of sessions are checked out." if ( self._database.close_inactive_transactions or self._database.logging_enabled diff --git a/google/cloud/spanner_v1/session.py b/google/cloud/spanner_v1/session.py index dfb8c0d4fc..3aa24354ad 100644 --- a/google/cloud/spanner_v1/session.py +++ b/google/cloud/spanner_v1/session.py @@ -99,23 +99,19 @@ def labels(self): @property def checkout_time(self): - """Get Check out time for session + """Check out time for the session. :rtype: time - :returns: the checkedout time for a session if assigned. + :returns: the checked out time for a session. """ return self._checkout_time @checkout_time.setter def checkout_time(self, value): - """Set Check out time for session - :type value: time - :param value: Checkout time - """ self._checkout_time = value @property def long_running(self): - """Test if the session is used for long running transaction. + """Whether the session is used for long running transaction. :rtype: bool :returns: True if session is long running, else False. """ @@ -123,15 +119,11 @@ def long_running(self): @long_running.setter def long_running(self, value): - """Sets if the session is used for long running transaction. - :type value: bool - :param value: bool - """ self._long_running = value @property def transaction_logged(self): - """Test if the session is already logged for long running transaction. + """Whether the session is already logged for long running transaction. :rtype: bool :returns: True if session is already logged for long running, else False. """ @@ -139,10 +131,6 @@ def transaction_logged(self): @transaction_logged.setter def transaction_logged(self, value): - """Sets if the session is already logged for long running transaction. - :type value: bool - :param value: bool - """ self._transaction_logged = value @property From d67884123d6229ae1d3cce239dd7d62adcf3f4c7 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Tue, 20 Jun 2023 12:30:46 +0530 Subject: [PATCH 11/24] Review comments --- google/cloud/spanner_v1/_helpers.py | 4 +- google/cloud/spanner_v1/database.py | 19 ++--- google/cloud/spanner_v1/pool.py | 109 ++++++++++++---------------- google/cloud/spanner_v1/session.py | 2 - tests/system/test_session_api.py | 46 +++++++++++- tests/unit/test_pool.py | 73 +++++++++++++++---- 6 files changed, 156 insertions(+), 97 deletions(-) diff --git a/google/cloud/spanner_v1/_helpers.py b/google/cloud/spanner_v1/_helpers.py index f938b96f40..cf73e5c050 100644 --- a/google/cloud/spanner_v1/_helpers.py +++ b/google/cloud/spanner_v1/_helpers.py @@ -39,8 +39,8 @@ ) # Constants -DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC = 120 -DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC = 3600 +DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC = 120 +DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC = 3600 def _try_to_coerce_bytes(bytestring): diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index 28da86f6f4..ca0fb0c9b7 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -1037,7 +1037,7 @@ class BatchCheckout(object): def __init__(self, database, request_options=None): self._database = database - self._batch = None + self._session = self._batch = None if request_options is None: self._request_options = RequestOptions() elif type(request_options) == dict: @@ -1047,12 +1047,12 @@ def __init__(self, database, request_options=None): def __enter__(self): """Begin ``with`` block.""" - session = self._database._pool.get() - self._batch = Batch(session) - session._batch = self._batch + session = self._session = self._database._pool.get() + batch = self._batch = Batch(session) + self._session._transaction = self._batch if self._request_options.transaction_tag: - self._batch.transaction_tag = self._request_options.transaction_tag - return self._batch + batch.transaction_tag = self._request_options.transaction_tag + return batch def __exit__(self, exc_type, exc_val, exc_tb): """End ``with`` block.""" @@ -1068,7 +1068,7 @@ def __exit__(self, exc_type, exc_val, exc_tb): "CommitStats: {}".format(self._batch.commit_stats), extra={"commit_stats": self._batch.commit_stats}, ) - if self._batch._session is not None: + if self._session._transaction is not None: self._database._pool.put(self._batch._session) @@ -1092,14 +1092,15 @@ class SnapshotCheckout(object): def __init__(self, database, **kw): self._database = database + self._session = None self._snapshot = None self._kw = kw def __enter__(self): """Begin ``with`` block.""" - session = self._database._pool.get() + session = self._session = self._database._pool.get() self._snapshot = Snapshot(session, **self._kw) - session._snapshot = self._snapshot + self._session._transaction = self._snapshot return self._snapshot def __exit__(self, exc_type, exc_val, exc_tb): diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index 0fe85a217f..420e12353a 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -27,7 +27,6 @@ _metadata_with_leader_aware_routing, ) from warnings import warn -from typing import List _NOW = datetime.datetime.utcnow # unit tests may replace @@ -138,18 +137,13 @@ def _new_session(self): labels=self.labels, database_role=self.database_role ) - def _format_trace(self, frames: List[traceback.FrameSummary]) -> str: - """Helper for formatting traceback frames into more readable trace. - :type frames: list[traceback.FrameSummary] - :param frames: list of stack frames - :rtype: str - :returns: fromatted trace. - """ - stack = [ - f"\n at {frame.name} ({frame.filename}:{frame.line}:{frame.lineno})" - for frame in frames - ] - return "".join(stack) + def _set_session_properties(self, session, isLongRunning): + """Helper for setting common session properties.""" + session.checkout_time = datetime.datetime.utcnow() + session.long_running = isLongRunning + session.transaction_logged = False + self._borrowed_sessions.append(session) + self._traces[session._session_id] = "".join(traceback.format_stack()) def session(self, **kwargs): """Check out a session from the pool. @@ -166,8 +160,8 @@ def session(self, **kwargs): def startCleaningLongRunningSessions(self): """Starts background task for recycling session.""" from google.cloud.spanner_v1._helpers import ( - DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, - DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC, + DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC, + DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC, ) if ( @@ -180,96 +174,98 @@ def startCleaningLongRunningSessions(self): background = threading.Thread( target=self.deleteLongRunningTransactions, args=( - DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, - DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC, + DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC, + DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC, ), daemon=True, name="recycle-sessions", ) background.start() + else: + AbstractSessionPool._cleanup_task_ongoing_event.set() def stopCleaningLongRunningSessions(self): """Stops background task for recycling session.""" AbstractSessionPool._cleanup_task_ongoing_event.clear() - AbstractSessionPool._cleanup_task_ongoing = False def deleteLongRunningTransactions( - self, longRunningTransactionInterval_sec, longRunningTransactionTimeout_sec + self, longRunningTransactionFrequency_sec, longRunningTransactionThreshold_sec ): """Recycles sessions with long-running transactions - :param longRunningTransactionInterval_sec: Interval for running background task in seconds. - :param longRunningTransactionTimeout_sec: Timeout for recycling sessions in seconds. + :param longRunningTransactionFrequency_sec: Interval for running background task in seconds. + :param longRunningTransactionThreshold_sec: Timeout for recycling sessions in seconds. """ long_running_transaction_timer = time.time() transactions_closed = 0 while AbstractSessionPool._cleanup_task_ongoing_event.is_set(): + AbstractSessionPool._cleanup_task_ongoing = True is_timeout_reached = ( time.time() - long_running_transaction_timer - >= longRunningTransactionTimeout_sec - + longRunningTransactionInterval_sec + >= longRunningTransactionThreshold_sec + + longRunningTransactionFrequency_sec ) if is_timeout_reached and transactions_closed == 0: break - - AbstractSessionPool._cleanup_task_ongoing = True iteration_start = time.time() - # Retrieve a list of sessions to delete + # Retrieve a list of sessions to delete. sessions_to_delete = [ session for session in self._borrowed_sessions if (datetime.datetime.utcnow() - session.checkout_time) - > datetime.timedelta(seconds=longRunningTransactionTimeout_sec) + > datetime.timedelta(seconds=longRunningTransactionThreshold_sec) and not session.long_running ] for session in sessions_to_delete: - self._recycle_session(session, transactions_closed) + transactions_closed += int(self._recycle_session(session)) # Calculate and sleep for the time remaining until the next iteration based on the interval. iteration_elapsed = time.time() - iteration_start - remaining_time = longRunningTransactionInterval_sec - iteration_elapsed + remaining_time = longRunningTransactionFrequency_sec - iteration_elapsed if remaining_time > 0: time.sleep(remaining_time) AbstractSessionPool._cleanup_task_ongoing = False AbstractSessionPool._cleanup_task_ongoing_event.clear() - def _recycle_session(self, session, transactions_closed): - """Helper method to recycle session for background task.""" - session_trace = self._format_trace(self._traces[session._session_id]) + def _recycle_session(self, session): + """Helper method to recycle session for background task. + :rtype: :bool + :returns: True if session is closed else False. + """ + session_recycled = False + session_trace = self._traces[session._session_id] if self._database.close_inactive_transactions: if self._database.logging_enabled: # Log a warning for a long-running transaction that has been closed - self._database.logger.warn( + self._database.logger.warning( "Long running transaction! Transaction has been closed as it was running for " + "more than 60 minutes. For long running transactions use batch or partitioned transactions. " + session_trace ) - # Set the session as None for associated objects (transaction, batch, snapshot) + # Set the session as None for associated transaction object if session._transaction is not None: session._transaction._session = None - if session._batch is not None: - session._batch._session = None - if session._snapshot is not None: - session._snapshot._session = None # Increment the count of closed transactions and return the session to the pool - transactions_closed += 1 + session_recycled = True self.put(session) elif self._database.logging_enabled: # Log a warning for a potentially leaking long-running transaction. # Only log the warning if it hasn't been logged already. if not session.transaction_logged: - self._database.logger.warn( + self._database.logger.warning( "Transaction has been running for longer than 60 minutes and might be causing a leak. " + "Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions. " + session_trace ) session.transaction_logged = True + return session_recycled + class FixedSizePool(AbstractSessionPool): """Concrete session pool implementation: @@ -370,24 +366,19 @@ def get(self, isLongRunning=False, timeout=None): session.create() # Set session properties. - session.checkout_time = datetime.datetime.utcnow() - session.long_running = isLongRunning - session.transaction_logged = False - self._borrowed_sessions.append(session) - self._traces[session._session_id] = traceback.extract_stack() + self._set_session_properties(session, isLongRunning) # Start background task for handling long-running transactions if 95% of sessions are checked out. if ( self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() - # Log a warning message if Session pool is exhausted. - if ( + elif ( self._database.logging_enabled and len(self._borrowed_sessions) / self.size == 1 ): - self._database.logger.warn("100% of the session pool is exhausted") + self._database.logger.warning("100% of the session pool is exhausted") return session @@ -483,24 +474,19 @@ def get(self, isLongRunning=False): session.create() # Set session properties. - session.checkout_time = datetime.datetime.utcnow() - session.long_running = isLongRunning - session.transaction_logged = False - self._borrowed_sessions.append(session) - self._traces[session._session_id] = traceback.extract_stack() + self._set_session_properties(session, isLongRunning) # Start background task for handling long-running transactions if 95% of sessions are checked out. if ( self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.target_size >= 0.95: self.startCleaningLongRunningSessions() - # Log a warning message if Session pool is exhausted. - if ( + elif ( self._database.logging_enabled and len(self._borrowed_sessions) / self.target_size == 1 ): - self._database.logger.warn("100% of the session pool is exhausted") + self._database.logger.warning("100% of the session pool is exhausted") return session @@ -656,24 +642,19 @@ def get(self, isLongRunning=False, timeout=None): session.create() # Set session properties. - session.checkout_time = datetime.datetime.utcnow() - session.long_running = isLongRunning - session.transaction_logged = False - self._borrowed_sessions.append(session) - self._traces[session._session_id] = traceback.extract_stack() + self._set_session_properties(session, isLongRunning) # Start background task for handling long-running transactions if 95% of sessions are checked out. if ( self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() - # Log a warning message if Session pool is exhausted. - if ( + elif ( self._database.logging_enabled and len(self._borrowed_sessions) / self.size == 1 ): - self._database.logger.warn("100% of the session pool is exhausted") + self._database.logger.warning("100% of the session pool is exhausted") return session def put(self, session): diff --git a/google/cloud/spanner_v1/session.py b/google/cloud/spanner_v1/session.py index 3aa24354ad..5a0b0dab79 100644 --- a/google/cloud/spanner_v1/session.py +++ b/google/cloud/spanner_v1/session.py @@ -62,8 +62,6 @@ class Session(object): _session_id = None _transaction = None - _batch = None - _snapshot = None def __init__(self, database, labels=None, database_role=None): self._database = database diff --git a/tests/system/test_session_api.py b/tests/system/test_session_api.py index c97b801017..d69f1b3683 100644 --- a/tests/system/test_session_api.py +++ b/tests/system/test_session_api.py @@ -2517,15 +2517,15 @@ def test_partition_query(sessions_database, not_emulator): batch_txn.close() -def test_should_close_inactive_transactions( +def test_should_close_inactive_transactions_with_bursty_pool( not_emulator, not_postgres, shared_instance, database_operation_timeout, databases_to_delete, ): - spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC = 2 - spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC = 5 + spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC = 2 + spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC = 5 database_name = _helpers.unique_id("test_longrunning", separator="_") pool = spanner_v1.BurstyPool(target_size=1) @@ -2544,7 +2544,7 @@ def test_should_close_inactive_transactions( def long_operation(transaction): transaction.execute_sql("SELECT 1") - time.sleep(20) + time.sleep(60) transaction.execute_sql("SELECT 1") with pytest.raises(Exception) as exc: @@ -2555,6 +2555,44 @@ def long_operation(transaction): ) +def test_should_close_inactive_transactions_with_fixedsize_pool( + not_emulator, + not_postgres, + shared_instance, + database_operation_timeout, + databases_to_delete, +): + spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC = 2 + spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC = 5 + database_name = _helpers.unique_id("test_longrunning", separator="_") + pool = spanner_v1.FixedSizePool(size=1, default_timeout=500) + + temp_db = shared_instance.database( + database_name, + close_inactive_transactions=True, + logging_enabled=True, + ) + + create_operation = temp_db.create() + create_operation.result(database_operation_timeout) + databases_to_delete.append(temp_db) + operation = temp_db.update_ddl(_helpers.DDL_STATEMENTS) + operation.result(database_operation_timeout) + + database = shared_instance.database(database_name, pool=pool) + + with pytest.raises(Exception) as exc: + with database.snapshot(multi_use=True) as snapshot: + snapshot.execute_sql("SELECT 1") + time.sleep(60) + snapshot.execute_sql("SELECT 1") + + assert ( + exc.value.args[0] + == "Transaction has been closed as it was running for more than 60 minutes" + ) + + class FauxCall: def __init__(self, code, details="FauxCall"): self._code = code diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 4635ec63c6..006ece8f03 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -17,14 +17,9 @@ import unittest import random import string -from time import sleep import threading import mock import datetime -from google.cloud.spanner_v1._helpers import ( - DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC, - DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC, -) def _make_database(name="name"): @@ -149,10 +144,10 @@ def test_startCleaningLongRunningSessions_success(self, mock_thread_class): pool._database = mock.MagicMock() pool._cleanup_task_ongoing_event.clear() with mock.patch( - "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_INTERVAL_SEC", + "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC", new=5, ), mock.patch( - "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_TIMEOUT_SEC", + "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC", new=10, ): pool.startCleaningLongRunningSessions() @@ -171,6 +166,52 @@ def test_startCleaningLongRunningSessions_success(self, mock_thread_class): pool.stopCleaningLongRunningSessions() self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + # @mock.patch("threading.Thread") + # def test_startCleaningLongRunningSessions_should_trigger_background_task_once(self, mock_thread_class): + # mock_thread = mock.MagicMock() + # mock_thread.start = mock.MagicMock() + # mock_thread_class.return_value = mock_thread + + # pool = self._make_one() + # pool._database = mock.MagicMock() + # pool._cleanup_task_ongoing_event.clear() + # with mock.patch( + # "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC", + # new=5, + # ), mock.patch( + # "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC", + # new=10, + # ): + # pool.startCleaningLongRunningSessions() + # threads = [] + # threads.append( + # threading.Thread( + # target=pool.startCleaningLongRunningSessions, + # ) + # ) + # threads.append( + # threading.Thread( + # target=pool.startCleaningLongRunningSessions, + # ) + # ) + # for thread in threads: + # thread.start() + + # for thread in threads: + # thread.join() + + # # A new thread should have been created to start the task + # threading.Thread.assert_called_once_with( + # target=pool.deleteLongRunningTransactions, + # args=(5, 10), + # daemon=True, + # name="recycle-sessions", + # ) + + # mock_thread.start.assert_called_once() + # pool.stopCleaningLongRunningSessions() + # self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + def test_stopCleaningLongRunningSessions(self): pool = self._make_one() pool._cleanup_task_ongoing_event.set() @@ -194,7 +235,7 @@ def put_side_effect(*args, **kwargs): pool._cleanup_task_ongoing_event.set() pool._database.close_inactive_transactions = close_inactive_transactions pool._borrowed_sessions = [] - pool._database.logger.warn = mock.MagicMock() + pool._database.logger.warning = mock.MagicMock() pool._format_trace = mock.MagicMock() return pool @@ -203,7 +244,7 @@ def test_deleteLongRunningTransactions_noSessionsToDelete(self): pool.deleteLongRunningTransactions(1, 1) # Assert that no warnings were logged and no sessions were put back - self.assertEqual(pool._database.logger.warn.call_count, 0) + self.assertEqual(pool._database.logger.warning.call_count, 0) pool.put.assert_not_called() self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) @@ -225,7 +266,7 @@ def test_deleteLongRunningTransactions_deleteAndLogSession(self): # Assert that the session was put back and a warning was logged pool.put.assert_called_once() - pool._database.logger.warn.assert_called_once() + pool._database.logger.warning.assert_called_once() self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) def test_deleteLongRunningTransactions_logSession(self): @@ -246,7 +287,7 @@ def test_deleteLongRunningTransactions_logSession(self): # Assert that the session was not put back and a warning was logged pool.put.assert_not_called() - pool._database.logger.warn.assert_called_once() + pool._database.logger.warning.assert_called_once() self.assertTrue(session.transaction_logged) self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) @@ -268,7 +309,7 @@ def test_deleteLongRunningTransactions_deleteSession(self): # Assert that the session was not put back and a warning was logged pool.put.assert_called_once() - pool._database.logger.warn.assert_not_called() + pool._database.logger.warning.assert_not_called() self.assertFalse(session.transaction_logged) self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) @@ -392,7 +433,7 @@ def test_get_trigger_longrunning_and_set_defaults(self): self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) # Fetch new session which will trigger the cleanup task. - session1 = pool.get() + pool.get() self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) pool.stopCleaningLongRunningSessions() @@ -535,7 +576,7 @@ def test_get_trigger_longrunning_and_set_defaults(self): self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) # Fetch new session which will trigger the cleanup task. - session1 = pool.get() + pool.get() self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) pool.stopCleaningLongRunningSessions() @@ -704,7 +745,7 @@ def test_get_trigger_longrunning_and_set_defaults(self): self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) # Fetch new session which will trigger the cleanup task. - session1 = pool.get() + pool.get() self.assertTrue(pool._cleanup_task_ongoing_event.is_set()) # Stop the background task. @@ -1210,7 +1251,7 @@ def __init__(self, name): self.logging_enabled = True self._logger = mock.MagicMock() self._logger.info = mock.MagicMock() - self._logger.warn = mock.MagicMock() + self._logger.warning = mock.MagicMock() def mock_batch_create_sessions( request=None, From 286e1f41f2222a66e1ce60df2474e2e3a1ffa93a Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Tue, 20 Jun 2023 17:49:35 +0530 Subject: [PATCH 12/24] fix system tests --- google/cloud/spanner_v1/database.py | 15 ++++++++------- google/cloud/spanner_v1/pool.py | 1 + 2 files changed, 9 insertions(+), 7 deletions(-) diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index ca0fb0c9b7..37f81c9d25 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -1068,8 +1068,9 @@ def __exit__(self, exc_type, exc_val, exc_tb): "CommitStats: {}".format(self._batch.commit_stats), extra={"commit_stats": self._batch.commit_stats}, ) - if self._session._transaction is not None: - self._database._pool.put(self._batch._session) + if self._batch._session is not None: + self._database._pool.put(self._session) + self._session._transaction = None class SnapshotCheckout(object): @@ -1105,15 +1106,15 @@ def __enter__(self): def __exit__(self, exc_type, exc_val, exc_tb): """End ``with`` block.""" - # self._snapshot._session is None that means session has been returned by background task if self._snapshot._session is not None: if isinstance(exc_val, NotFound): # If NotFound exception occurs inside the with block # then we validate if the session still exists. - if not self._snapshot._session.exists(): - self._snapshot._session = self._database._pool._new_session() - self._snapshot._session.create() - self._database._pool.put(self._snapshot._session) + if not self._session.exists(): + self._session = self._database._pool._new_session() + self._session.create() + self._database._pool.put(self._session) + self._session._transaction = None class BatchSnapshot(object): diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index 420e12353a..e30e7f1a66 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -848,3 +848,4 @@ def __exit__(self, *ignored): and self._session._transaction._session is None ): self._pool.put(self._session) + self._session._transaction = None From be6eee32f96c769004727a0ede6ca95909e31d25 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Wed, 21 Jun 2023 15:07:48 +0530 Subject: [PATCH 13/24] review comments --- google/cloud/spanner_v1/pool.py | 12 ++++-- tests/system/test_session_api.py | 73 +++++++++++++++++++++++++++++--- 2 files changed, 75 insertions(+), 10 deletions(-) diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index e30e7f1a66..a1ad8f5ad9 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -404,8 +404,9 @@ def put(self, session): self.stopCleaningLongRunningSessions() def clear(self): - """Delete all sessions in the pool.""" + """Delete all sessions in the pool and stops the background cleanup task.""" + self.stopCleaningLongRunningSessions() while True: try: session = self._sessions.get(block=False) @@ -518,7 +519,9 @@ def put(self, session): pass def clear(self): - """Delete all sessions in the pool.""" + """Delete all sessions in the pool and stops the background cleanup task.""" + + self.stopCleaningLongRunningSessions() while True: try: @@ -679,7 +682,10 @@ def put(self, session): self.stopCleaningLongRunningSessions() def clear(self): - """Delete all sessions in the pool.""" + """Delete all sessions in the pool and stops the background cleanup task.""" + + self.stopCleaningLongRunningSessions() + while True: try: _, session = self._sessions.get(block=False) diff --git a/tests/system/test_session_api.py b/tests/system/test_session_api.py index d69f1b3683..cc463b49ba 100644 --- a/tests/system/test_session_api.py +++ b/tests/system/test_session_api.py @@ -2517,15 +2517,17 @@ def test_partition_query(sessions_database, not_emulator): batch_txn.close() -def test_should_close_inactive_transactions_with_bursty_pool( +def test_should_close_inactive_transactions_with_bursty_pool_and_transaction( not_emulator, not_postgres, shared_instance, database_operation_timeout, databases_to_delete, ): + # Overriding the frequency and threshold to smaller value to simulate the behavior. spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC = 2 spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC = 5 + database_name = _helpers.unique_id("test_longrunning", separator="_") pool = spanner_v1.BurstyPool(target_size=1) @@ -2544,7 +2546,7 @@ def test_should_close_inactive_transactions_with_bursty_pool( def long_operation(transaction): transaction.execute_sql("SELECT 1") - time.sleep(60) + time.sleep(10) transaction.execute_sql("SELECT 1") with pytest.raises(Exception) as exc: @@ -2555,22 +2557,22 @@ def long_operation(transaction): ) -def test_should_close_inactive_transactions_with_fixedsize_pool( +def test_should_close_inactive_transactions_with_fixedsize_pool_and_snapshot( not_emulator, not_postgres, shared_instance, database_operation_timeout, databases_to_delete, ): + # Overriding the frequency and threshold to smaller value to simulate the behavior. spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC = 2 spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC = 5 + database_name = _helpers.unique_id("test_longrunning", separator="_") pool = spanner_v1.FixedSizePool(size=1, default_timeout=500) temp_db = shared_instance.database( database_name, - close_inactive_transactions=True, - logging_enabled=True, ) create_operation = temp_db.create() @@ -2579,12 +2581,17 @@ def test_should_close_inactive_transactions_with_fixedsize_pool( operation = temp_db.update_ddl(_helpers.DDL_STATEMENTS) operation.result(database_operation_timeout) - database = shared_instance.database(database_name, pool=pool) + database = shared_instance.database( + database_name, + pool=pool, + close_inactive_transactions=True, + logging_enabled=True, + ) with pytest.raises(Exception) as exc: with database.snapshot(multi_use=True) as snapshot: snapshot.execute_sql("SELECT 1") - time.sleep(60) + time.sleep(10) snapshot.execute_sql("SELECT 1") assert ( @@ -2593,6 +2600,58 @@ def test_should_close_inactive_transactions_with_fixedsize_pool( ) +def test_should_close_inactive_transactions_with_pinging_pool_and_batch( + not_emulator, + not_postgres, + shared_instance, + database_operation_timeout, + databases_to_delete, +): + # Overriding the frequency and threshold to smaller value to simulate the behavior. + spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC = 2 + spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC = 5 + + database_name = _helpers.unique_id("test_longrunning", separator="_") + pool = spanner_v1.PingingPool(size=1, default_timeout=500) + + temp_db = shared_instance.database( + database_name, + ) + + create_operation = temp_db.create() + create_operation.result(database_operation_timeout) + databases_to_delete.append(temp_db) + operation = temp_db.update_ddl(_helpers.DDL_STATEMENTS) + operation.result(database_operation_timeout) + + database = shared_instance.database( + database_name, + pool=pool, + close_inactive_transactions=True, + logging_enabled=True, + ) + + table = "contacts" + columns = ["contact_id", "first_name", "last_name", "email"] + rowdata1 = [ + (1, "Alex", "Alex", "testemail@email.com"), + ] + rowdata2 = [ + (2, "Alexander", "Alexander", "testemail@email.com"), + ] + + with pytest.raises(Exception) as exc: + with database.batch() as batch: + batch.insert(table, columns, rowdata1) + batch.insert(table, columns, rowdata2) + time.sleep(10) + + assert ( + exc.value.args[0] + == "Transaction has been closed as it was running for more than 60 minutes" + ) + + class FauxCall: def __init__(self, code, details="FauxCall"): self._code = code From 86a25525e9880a10d89618762f083173d066946a Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Wed, 21 Jun 2023 15:13:22 +0530 Subject: [PATCH 14/24] review comments --- tests/unit/test_pool.py | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 006ece8f03..08c98198f8 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -506,8 +506,10 @@ def test_clear(self): for session in SESSIONS: session.create.assert_not_called() + pool._cleanup_task_ongoing_event.set() pool.clear() + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) for session in SESSIONS: self.assertTrue(session._deleted) @@ -647,9 +649,10 @@ def test_clear(self): pool.bind(database) previous = _Session(database) pool.put(previous) - + pool._cleanup_task_ongoing_event.set() + pool.clear() - + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) self.assertTrue(previous._deleted) @@ -869,9 +872,11 @@ def test_clear(self): self.assertEqual(api.batch_create_sessions.call_count, 5) for session in SESSIONS: session.create.assert_not_called() + pool._cleanup_task_ongoing_event.set() pool.clear() + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) for session in SESSIONS: self.assertTrue(session._deleted) From c33f93000919298c0a7a29f25598136f5946b7b2 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Thu, 22 Jun 2023 12:18:32 +0530 Subject: [PATCH 15/24] review comments --- google/cloud/spanner_v1/pool.py | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index a1ad8f5ad9..e2ab4eca15 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -373,10 +373,11 @@ def get(self, isLongRunning=False, timeout=None): self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() + # Log a warning message if Session pool is exhausted. - elif ( + if ( self._database.logging_enabled - and len(self._borrowed_sessions) / self.size == 1 + and len(self._borrowed_sessions) == self.size ): self._database.logger.warning("100% of the session pool is exhausted") @@ -482,10 +483,11 @@ def get(self, isLongRunning=False): self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.target_size >= 0.95: self.startCleaningLongRunningSessions() + # Log a warning message if Session pool is exhausted. - elif ( + if ( self._database.logging_enabled - and len(self._borrowed_sessions) / self.target_size == 1 + and len(self._borrowed_sessions) == self.target_size ): self._database.logger.warning("100% of the session pool is exhausted") @@ -652,10 +654,11 @@ def get(self, isLongRunning=False, timeout=None): self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() + # Log a warning message if Session pool is exhausted. - elif ( + if ( self._database.logging_enabled - and len(self._borrowed_sessions) / self.size == 1 + and len(self._borrowed_sessions) == self.size ): self._database.logger.warning("100% of the session pool is exhausted") return session From cb748d897a71f2ccc7312df24022e59b22ec9133 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Thu, 22 Jun 2023 13:36:14 +0530 Subject: [PATCH 16/24] lint --- google/cloud/spanner_v1/pool.py | 16 +++++----------- tests/unit/test_pool.py | 2 +- 2 files changed, 6 insertions(+), 12 deletions(-) diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index e2ab4eca15..c87992f994 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -373,12 +373,9 @@ def get(self, isLongRunning=False, timeout=None): self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() - + # Log a warning message if Session pool is exhausted. - if ( - self._database.logging_enabled - and len(self._borrowed_sessions) == self.size - ): + if self._database.logging_enabled and len(self._borrowed_sessions) == self.size: self._database.logger.warning("100% of the session pool is exhausted") return session @@ -483,7 +480,7 @@ def get(self, isLongRunning=False): self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.target_size >= 0.95: self.startCleaningLongRunningSessions() - + # Log a warning message if Session pool is exhausted. if ( self._database.logging_enabled @@ -654,12 +651,9 @@ def get(self, isLongRunning=False, timeout=None): self._database.close_inactive_transactions or self._database.logging_enabled ) and len(self._borrowed_sessions) / self.size >= 0.95: self.startCleaningLongRunningSessions() - + # Log a warning message if Session pool is exhausted. - if ( - self._database.logging_enabled - and len(self._borrowed_sessions) == self.size - ): + if self._database.logging_enabled and len(self._borrowed_sessions) == self.size: self._database.logger.warning("100% of the session pool is exhausted") return session diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 08c98198f8..91356bbbc2 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -650,7 +650,7 @@ def test_clear(self): previous = _Session(database) pool.put(previous) pool._cleanup_task_ongoing_event.set() - + pool.clear() self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) self.assertTrue(previous._deleted) From 1b72281751eb1ecc5bedd24dbe895a8876da3d54 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Thu, 22 Jun 2023 14:30:11 +0530 Subject: [PATCH 17/24] unit test --- tests/unit/test_pool.py | 101 ++++++++++++++++++++++------------------ 1 file changed, 56 insertions(+), 45 deletions(-) diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 91356bbbc2..70a6b2a0fb 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -166,51 +166,62 @@ def test_startCleaningLongRunningSessions_success(self, mock_thread_class): pool.stopCleaningLongRunningSessions() self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) - # @mock.patch("threading.Thread") - # def test_startCleaningLongRunningSessions_should_trigger_background_task_once(self, mock_thread_class): - # mock_thread = mock.MagicMock() - # mock_thread.start = mock.MagicMock() - # mock_thread_class.return_value = mock_thread - - # pool = self._make_one() - # pool._database = mock.MagicMock() - # pool._cleanup_task_ongoing_event.clear() - # with mock.patch( - # "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC", - # new=5, - # ), mock.patch( - # "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC", - # new=10, - # ): - # pool.startCleaningLongRunningSessions() - # threads = [] - # threads.append( - # threading.Thread( - # target=pool.startCleaningLongRunningSessions, - # ) - # ) - # threads.append( - # threading.Thread( - # target=pool.startCleaningLongRunningSessions, - # ) - # ) - # for thread in threads: - # thread.start() - - # for thread in threads: - # thread.join() - - # # A new thread should have been created to start the task - # threading.Thread.assert_called_once_with( - # target=pool.deleteLongRunningTransactions, - # args=(5, 10), - # daemon=True, - # name="recycle-sessions", - # ) - - # mock_thread.start.assert_called_once() - # pool.stopCleaningLongRunningSessions() - # self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) + @mock.patch("threading.Thread") + def test_startCleaningLongRunningSessions_should_trigger_background_task_once( + self, mock_thread_class + ): + mock_thread = mock.MagicMock() + mock_thread.start = mock.MagicMock() + mock_thread_class.return_value = mock_thread + + pool = self._make_one() + pool._database = mock.MagicMock() + pool._cleanup_task_ongoing_event.clear() + with mock.patch( + "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC", + new=5, + ), mock.patch( + "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC", + new=10, + ): + pool.startCleaningLongRunningSessions() + + # Calling start and stop background task multiple times. Background should get trigerred only once. + threads = [] + threads.append( + threading.Thread( + target=pool.startCleaningLongRunningSessions, + ) + ) + threads.append( + threading.Thread( + target=pool.stopCleaningLongRunningSessions, + ) + ) + threads.append( + threading.Thread( + target=pool.startCleaningLongRunningSessions, + ) + ) + for thread in threads: + thread.start() + + for thread in threads: + thread.join() + + # A new thread should have been created to start the task + deleteLongRunningTransactions_calls = sum( + [ + 1 + for call in threading.Thread.mock_calls + if "deleteLongRunningTransactions" in call.kwargs.__str__() + ] + ) + + self.assertEqual(deleteLongRunningTransactions_calls, 1) + + pool.stopCleaningLongRunningSessions() + self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) def test_stopCleaningLongRunningSessions(self): pool = self._make_one() From ac9e0e4b72bd3d5827ebf18b93463881c2deadf1 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Mon, 3 Jul 2023 15:58:04 +0530 Subject: [PATCH 18/24] review comments --- google/cloud/spanner_v1/database.py | 4 +-- google/cloud/spanner_v1/pool.py | 53 ++++++++++++++++++++--------- tests/unit/test_pool.py | 2 ++ 3 files changed, 40 insertions(+), 19 deletions(-) diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index 37f81c9d25..d4cb049f7f 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -109,7 +109,7 @@ class Database(object): :class:`~google.cloud.spanner_v1.pool.BurstyPool`. :type logging_enabled: boolean - :parama logging_enabled: (Optional) Represents whether the database + :param logging_enabled: (Optional) Represents whether the database has logging enabled or not. Default is True :type logger: :class:`logging.Logger` @@ -1049,7 +1049,7 @@ def __enter__(self): """Begin ``with`` block.""" session = self._session = self._database._pool.get() batch = self._batch = Batch(session) - self._session._transaction = self._batch + self._session._transaction = batch if self._request_options.transaction_tag: batch.transaction_tag = self._request_options.transaction_tag return batch diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index c87992f994..b418280e7a 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -49,6 +49,7 @@ class AbstractSessionPool(object): _cleanup_task_ongoing_event = threading.Event() _cleanup_task_ongoing = False + _used_sessions_ratio_threshold = 0.95 def __init__(self, labels=None, database_role=None): if labels is None: @@ -170,7 +171,9 @@ def startCleaningLongRunningSessions(self): ): AbstractSessionPool._cleanup_task_ongoing_event.set() if self._database.logging_enabled: - self._database.logger.info("95% of the session pool is exhausted") + self._database.logger.info( + f"{self._used_sessions_ratio_threshold * 100}% of the session pool is exhausted" + ) background = threading.Thread( target=self.deleteLongRunningTransactions, args=( @@ -219,7 +222,9 @@ def deleteLongRunningTransactions( ] for session in sessions_to_delete: - transactions_closed += int(self._recycle_session(session)) + transactions_closed += int( + self._close_long_running_transactions(session) + ) # Calculate and sleep for the time remaining until the next iteration based on the interval. iteration_elapsed = time.time() - iteration_start @@ -230,7 +235,7 @@ def deleteLongRunningTransactions( AbstractSessionPool._cleanup_task_ongoing = False AbstractSessionPool._cleanup_task_ongoing_event.clear() - def _recycle_session(self, session): + def _close_long_running_transactions(self, session): """Helper method to recycle session for background task. :rtype: :bool :returns: True if session is closed else False. @@ -368,10 +373,12 @@ def get(self, isLongRunning=False, timeout=None): # Set session properties. self._set_session_properties(session, isLongRunning) - # Start background task for handling long-running transactions if 95% of sessions are checked out. + # Start background task for handling long-running transactions if used session threshold has reached. if ( self._database.close_inactive_transactions or self._database.logging_enabled - ) and len(self._borrowed_sessions) / self.size >= 0.95: + ) and len( + self._borrowed_sessions + ) / self.size >= self._used_sessions_ratio_threshold: self.startCleaningLongRunningSessions() # Log a warning message if Session pool is exhausted. @@ -395,10 +402,12 @@ def put(self, session): self._sessions.put_nowait(session) self._traces.pop(session._session_id, None) - # Stop background task for handling long running transactions if less than 95% of sessions are checked out." + # Stop background task for handling long running transactions if used sessions are less the threshold" if ( self._database.close_inactive_transactions or self._database.logging_enabled - ) and len(self._borrowed_sessions) / self.size < 0.95: + ) and len( + self._borrowed_sessions + ) / self.size < self._used_sessions_ratio_threshold: self.stopCleaningLongRunningSessions() def clear(self): @@ -475,10 +484,12 @@ def get(self, isLongRunning=False): # Set session properties. self._set_session_properties(session, isLongRunning) - # Start background task for handling long-running transactions if 95% of sessions are checked out. + # Start background task for handling long-running transactions if used sessions threshold has reached. if ( self._database.close_inactive_transactions or self._database.logging_enabled - ) and len(self._borrowed_sessions) / self.target_size >= 0.95: + ) and len( + self._borrowed_sessions + ) / self.target_size >= self._used_sessions_ratio_threshold: self.startCleaningLongRunningSessions() # Log a warning message if Session pool is exhausted. @@ -505,11 +516,13 @@ def put(self, session): self._sessions.put_nowait(session) self._traces.pop(session._session_id, None) - # Stop background task for handling long running transactions if less than 95% of sessions are checked out." + # Stop background task for handling long running transactions if used sessions are less then threshold." if ( self._database.close_inactive_transactions or self._database.logging_enabled - ) and len(self._borrowed_sessions) / self.target_size < 0.95: + ) and len( + self._borrowed_sessions + ) / self.target_size < self._used_sessions_ratio_threshold: self.stopCleaningLongRunningSessions() except queue.Full: try: @@ -646,10 +659,12 @@ def get(self, isLongRunning=False, timeout=None): # Set session properties. self._set_session_properties(session, isLongRunning) - # Start background task for handling long-running transactions if 95% of sessions are checked out. + # Start background task for handling long-running transactions if used sessions threshold has reached. if ( self._database.close_inactive_transactions or self._database.logging_enabled - ) and len(self._borrowed_sessions) / self.size >= 0.95: + ) and len( + self._borrowed_sessions + ) / self.size >= self._used_sessions_ratio_threshold: self.startCleaningLongRunningSessions() # Log a warning message if Session pool is exhausted. @@ -672,10 +687,12 @@ def put(self, session): self._sessions.put_nowait((_NOW() + self._delta, session)) self._traces.pop(session._session_id, None) - # Stop background task for handling long running transactions if less than 95% of sessions are checked out." + # Stop background task for handling long running transactions if used sessions are less then the threshold" if ( self._database.close_inactive_transactions or self._database.logging_enabled - ) and len(self._borrowed_sessions) / self.size < 0.95: + ) and len( + self._borrowed_sessions + ) / self.size < self._used_sessions_ratio_threshold: self.stopCleaningLongRunningSessions() def clear(self): @@ -809,11 +826,13 @@ def put(self, session): self._pending_sessions.put(session) self._traces.pop(session._session_id, None) - # Stop background task for handling long running transactions if less than 95% of sessions are checked out." + # Stop background task for handling long running transactions if used sessions are less then threshold." if ( self._database.close_inactive_transactions or self._database.logging_enabled - ) and len(self._borrowed_sessions) / self.size < 0.95: + ) and len( + self._borrowed_sessions + ) / self.size < self._used_sessions_ratio_threshold: self.stopCleaningLongRunningSessions() else: super(TransactionPingingPool, self).put(session) diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 70a6b2a0fb..30a90c392c 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -176,6 +176,7 @@ def test_startCleaningLongRunningSessions_should_trigger_background_task_once( pool = self._make_one() pool._database = mock.MagicMock() + pool._database.logging_enabled = True pool._cleanup_task_ongoing_event.clear() with mock.patch( "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC", @@ -219,6 +220,7 @@ def test_startCleaningLongRunningSessions_should_trigger_background_task_once( ) self.assertEqual(deleteLongRunningTransactions_calls, 1) + self.assertEqual(pool._database.logger.info.mock_calls[0].args[0].__str__(), "95.0% of the session pool is exhausted") pool.stopCleaningLongRunningSessions() self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) From ff8674db5edfe6b7824be99ec603294898b0563c Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Mon, 3 Jul 2023 17:28:27 +0530 Subject: [PATCH 19/24] review comments --- google/cloud/spanner_v1/pool.py | 8 ++++---- tests/unit/test_pool.py | 5 ++++- tests/unit/test_snapshot.py | 4 ++-- 3 files changed, 10 insertions(+), 7 deletions(-) diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index b418280e7a..40aaa58a94 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -216,9 +216,9 @@ def deleteLongRunningTransactions( sessions_to_delete = [ session for session in self._borrowed_sessions - if (datetime.datetime.utcnow() - session.checkout_time) + if not session.long_running + and (datetime.datetime.utcnow() - session.checkout_time) > datetime.timedelta(seconds=longRunningTransactionThreshold_sec) - and not session.long_running ] for session in sessions_to_delete: @@ -236,9 +236,9 @@ def deleteLongRunningTransactions( AbstractSessionPool._cleanup_task_ongoing_event.clear() def _close_long_running_transactions(self, session): - """Helper method to recycle session for background task. + """Helper method to close long running transactions. :rtype: :bool - :returns: True if session is closed else False. + :returns: True if transaction is closed else False. """ session_recycled = False session_trace = self._traces[session._session_id] diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index 30a90c392c..a90813dcda 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -220,7 +220,10 @@ def test_startCleaningLongRunningSessions_should_trigger_background_task_once( ) self.assertEqual(deleteLongRunningTransactions_calls, 1) - self.assertEqual(pool._database.logger.info.mock_calls[0].args[0].__str__(), "95.0% of the session pool is exhausted") + self.assertEqual( + pool._database.logger.info.mock_calls[0].args[0].__str__(), + "95.0% of the session pool is exhausted", + ) pool.stopCleaningLongRunningSessions() self.assertFalse(pool._cleanup_task_ongoing_event.is_set()) diff --git a/tests/unit/test_snapshot.py b/tests/unit/test_snapshot.py index c90b58725e..c5131fdee2 100644 --- a/tests/unit/test_snapshot.py +++ b/tests/unit/test_snapshot.py @@ -1168,7 +1168,7 @@ def test_partition_read_other_error(self): ), ) - def test_partition_read_should_throw_error_for_recycled_session(self): + def test_partition_read_should_throw_error_is_session_is_none(self): from google.cloud.spanner_v1.keyset import KeySet keyset = KeySet(all_=True) @@ -1343,7 +1343,7 @@ def test_partition_query_other_error(self): attributes=dict(BASE_ATTRIBUTES, **{"db.statement": SQL_QUERY}), ) - def test_partition_query_should_throw_error_for_recycled_session(self): + def test_partition_query_should_throw_error_if_session_is_none(self): session = _Session() derived = self._makeDerived(session) derived._session = None From 5a0945084066f25de027ece3baa444d605fa1ef6 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Tue, 4 Jul 2023 22:58:47 +0530 Subject: [PATCH 20/24] review commemts --- google/cloud/spanner_dbapi/connection.py | 15 ++-- google/cloud/spanner_v1/database.py | 14 --- google/cloud/spanner_v1/instance.py | 6 -- google/cloud/spanner_v1/pool.py | 96 ++++++++++++++------- tests/system/test_session_api.py | 3 - tests/unit/spanner_dbapi/test_connect.py | 2 - tests/unit/spanner_dbapi/test_connection.py | 6 +- tests/unit/test_database.py | 15 ---- tests/unit/test_pool.py | 33 +++++-- 9 files changed, 103 insertions(+), 87 deletions(-) diff --git a/google/cloud/spanner_dbapi/connection.py b/google/cloud/spanner_dbapi/connection.py index d30a1f806e..f6a42eaa3a 100644 --- a/google/cloud/spanner_dbapi/connection.py +++ b/google/cloud/spanner_dbapi/connection.py @@ -582,17 +582,18 @@ def connect( raise ValueError("project in url does not match client object project") instance = client.instance(instance_id) - conn = Connection( - instance, - instance.database( + + if database_id: + database = instance.database( database_id, pool=pool, - logging_enabled=False, close_inactive_transactions=False, ) - if database_id - else None, - ) + database._pool.logging_enabled = False + else: + database = None + + conn = Connection(instance, database) if pool is not None: conn._own_pool = False diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index d4cb049f7f..84418d7b76 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -108,10 +108,6 @@ class Database(object): passed, the database will construct an instance of :class:`~google.cloud.spanner_v1.pool.BurstyPool`. - :type logging_enabled: boolean - :param logging_enabled: (Optional) Represents whether the database - has logging enabled or not. Default is True - :type logger: :class:`logging.Logger` :param logger: (Optional) a custom logger that is used if `log_commit_stats` is `True` to log commit statistics. If not passed, a logger @@ -150,7 +146,6 @@ def __init__( instance, ddl_statements=(), pool=None, - logging_enabled=True, logger=None, close_inactive_transactions=False, encryption_config=None, @@ -170,7 +165,6 @@ def __init__( self._encryption_info = None self._default_leader = None self.log_commit_stats = False - self._logging_enabled = logging_enabled self._logger = logger self._close_inactive_transactions = close_inactive_transactions self._encryption_config = encryption_config @@ -352,14 +346,6 @@ def database_role(self): """ return self._database_role - @property - def logging_enabled(self): - """Whether the database has logging enabled. Default: True. - :rtype: bool - :returns: True if logging is enabled, else False. - """ - return self._logging_enabled - @property def reconciling(self): """Whether the database is currently reconciling. diff --git a/google/cloud/spanner_v1/instance.py b/google/cloud/spanner_v1/instance.py index 0f090a2a96..90bca393f3 100644 --- a/google/cloud/spanner_v1/instance.py +++ b/google/cloud/spanner_v1/instance.py @@ -428,7 +428,6 @@ def database( database_id, ddl_statements=(), pool=None, - logging_enabled=True, logger=None, close_inactive_transactions=False, encryption_config=None, @@ -449,10 +448,6 @@ def database( :class:`~google.cloud.spanner_v1.pool.AbstractSessionPool`. :param pool: (Optional) session pool to be used by database. - :type logging_enabled: boolean - :param logging_enabled: (Optional) Represents whether the database - has logging enabled or not. Default is True - :type logger: :class:`logging.Logger` :param logger: (Optional) a custom logger that is used if `log_commit_stats` is `True` to log commit statistics. If not passed, a logger @@ -490,7 +485,6 @@ def database( self, ddl_statements=ddl_statements, pool=pool, - logging_enabled=logging_enabled, logger=logger, close_inactive_transactions=close_inactive_transactions, encryption_config=encryption_config, diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index 40aaa58a94..8c701672ff 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -40,6 +40,10 @@ class AbstractSessionPool(object): :type database_role: str :param database_role: (Optional) user-assigned database_role for the session. + + :type logging_enabled: boolean + :param logging_enabled: (Optional) Represents whether the session pool + has logging enabled or not. Default is True """ _database = None @@ -51,11 +55,12 @@ class AbstractSessionPool(object): _cleanup_task_ongoing = False _used_sessions_ratio_threshold = 0.95 - def __init__(self, labels=None, database_role=None): + def __init__(self, labels=None, database_role=None, logging_enabled=True): if labels is None: labels = {} self._labels = labels self._database_role = database_role + self._logging_enabled = logging_enabled @property def labels(self): @@ -75,6 +80,18 @@ def database_role(self): """ return self._database_role + @property + def logging_enabled(self): + """Whether the session pool has logging enabled. Default: True. + :rtype: bool + :returns: True if logging is enabled, else False. + """ + return self._logging_enabled + + @logging_enabled.setter + def logging_enabled(self, value): + self._logging_enabled = value + def bind(self, database): """Associate the pool with a database. @@ -170,7 +187,7 @@ def startCleaningLongRunningSessions(self): and not AbstractSessionPool._cleanup_task_ongoing ): AbstractSessionPool._cleanup_task_ongoing_event.set() - if self._database.logging_enabled: + if self.logging_enabled: self._database.logger.info( f"{self._used_sessions_ratio_threshold * 100}% of the session pool is exhausted" ) @@ -243,7 +260,7 @@ def _close_long_running_transactions(self, session): session_recycled = False session_trace = self._traces[session._session_id] if self._database.close_inactive_transactions: - if self._database.logging_enabled: + if self.logging_enabled: # Log a warning for a long-running transaction that has been closed self._database.logger.warning( "Long running transaction! Transaction has been closed as it was running for " @@ -258,7 +275,7 @@ def _close_long_running_transactions(self, session): # Increment the count of closed transactions and return the session to the pool session_recycled = True self.put(session) - elif self._database.logging_enabled: + elif self.logging_enabled: # Log a warning for a potentially leaking long-running transaction. # Only log the warning if it hasn't been logged already. if not session.transaction_logged: @@ -300,6 +317,10 @@ class FixedSizePool(AbstractSessionPool): :type database_role: str :param database_role: (Optional) user-assigned database_role for the session. + + :type logging_enabled: boolean + :param logging_enabled: (Optional) Represents whether the session pool + has logging enabled or not. Default is True """ DEFAULT_SIZE = 10 @@ -311,8 +332,11 @@ def __init__( default_timeout=DEFAULT_TIMEOUT, labels=None, database_role=None, + logging_enabled=True, ): - super(FixedSizePool, self).__init__(labels=labels, database_role=database_role) + super(FixedSizePool, self).__init__( + labels=labels, database_role=database_role, logging_enabled=logging_enabled + ) self.size = size self.default_timeout = default_timeout self._sessions = queue.LifoQueue(size) @@ -374,15 +398,13 @@ def get(self, isLongRunning=False, timeout=None): self._set_session_properties(session, isLongRunning) # Start background task for handling long-running transactions if used session threshold has reached. - if ( - self._database.close_inactive_transactions or self._database.logging_enabled - ) and len( + if (self._database.close_inactive_transactions or self.logging_enabled) and len( self._borrowed_sessions ) / self.size >= self._used_sessions_ratio_threshold: self.startCleaningLongRunningSessions() # Log a warning message if Session pool is exhausted. - if self._database.logging_enabled and len(self._borrowed_sessions) == self.size: + if self.logging_enabled and len(self._borrowed_sessions) == self.size: self._database.logger.warning("100% of the session pool is exhausted") return session @@ -403,9 +425,7 @@ def put(self, session): self._traces.pop(session._session_id, None) # Stop background task for handling long running transactions if used sessions are less the threshold" - if ( - self._database.close_inactive_transactions or self._database.logging_enabled - ) and len( + if (self._database.close_inactive_transactions or self.logging_enabled) and len( self._borrowed_sessions ) / self.size < self._used_sessions_ratio_threshold: self.stopCleaningLongRunningSessions() @@ -444,10 +464,18 @@ class BurstyPool(AbstractSessionPool): :type database_role: str :param database_role: (Optional) user-assigned database_role for the session. + + :type logging_enabled: boolean + :param logging_enabled: (Optional) Represents whether the session pool + has logging enabled or not. Default is True """ - def __init__(self, target_size=10, labels=None, database_role=None): - super(BurstyPool, self).__init__(labels=labels, database_role=database_role) + def __init__( + self, target_size=10, labels=None, database_role=None, logging_enabled=True + ): + super(BurstyPool, self).__init__( + labels=labels, database_role=database_role, logging_enabled=logging_enabled + ) self.target_size = target_size self._database = None self._sessions = queue.LifoQueue(target_size) @@ -485,18 +513,13 @@ def get(self, isLongRunning=False): self._set_session_properties(session, isLongRunning) # Start background task for handling long-running transactions if used sessions threshold has reached. - if ( - self._database.close_inactive_transactions or self._database.logging_enabled - ) and len( + if (self._database.close_inactive_transactions or self.logging_enabled) and len( self._borrowed_sessions ) / self.target_size >= self._used_sessions_ratio_threshold: self.startCleaningLongRunningSessions() # Log a warning message if Session pool is exhausted. - if ( - self._database.logging_enabled - and len(self._borrowed_sessions) == self.target_size - ): + if self.logging_enabled and len(self._borrowed_sessions) == self.target_size: self._database.logger.warning("100% of the session pool is exhausted") return session @@ -518,8 +541,7 @@ def put(self, session): # Stop background task for handling long running transactions if used sessions are less then threshold." if ( - self._database.close_inactive_transactions - or self._database.logging_enabled + self._database.close_inactive_transactions or self.logging_enabled ) and len( self._borrowed_sessions ) / self.target_size < self._used_sessions_ratio_threshold: @@ -580,6 +602,10 @@ class PingingPool(AbstractSessionPool): :type database_role: str :param database_role: (Optional) user-assigned database_role for the session. + + :type logging_enabled: boolean + :param logging_enabled: (Optional) Represents whether the session pool + has logging enabled or not. Default is True """ def __init__( @@ -589,8 +615,11 @@ def __init__( ping_interval=3000, labels=None, database_role=None, + logging_enabled=True, ): - super(PingingPool, self).__init__(labels=labels, database_role=database_role) + super(PingingPool, self).__init__( + labels=labels, database_role=database_role, logging_enabled=logging_enabled + ) self.size = size self.default_timeout = default_timeout self._delta = datetime.timedelta(seconds=ping_interval) @@ -660,15 +689,13 @@ def get(self, isLongRunning=False, timeout=None): self._set_session_properties(session, isLongRunning) # Start background task for handling long-running transactions if used sessions threshold has reached. - if ( - self._database.close_inactive_transactions or self._database.logging_enabled - ) and len( + if (self._database.close_inactive_transactions or self.logging_enabled) and len( self._borrowed_sessions ) / self.size >= self._used_sessions_ratio_threshold: self.startCleaningLongRunningSessions() # Log a warning message if Session pool is exhausted. - if self._database.logging_enabled and len(self._borrowed_sessions) == self.size: + if self.logging_enabled and len(self._borrowed_sessions) == self.size: self._database.logger.warning("100% of the session pool is exhausted") return session @@ -688,9 +715,7 @@ def put(self, session): self._traces.pop(session._session_id, None) # Stop background task for handling long running transactions if used sessions are less then the threshold" - if ( - self._database.close_inactive_transactions or self._database.logging_enabled - ) and len( + if (self._database.close_inactive_transactions or self.logging_enabled) and len( self._borrowed_sessions ) / self.size < self._used_sessions_ratio_threshold: self.stopCleaningLongRunningSessions() @@ -764,6 +789,10 @@ class TransactionPingingPool(PingingPool): :type database_role: str :param database_role: (Optional) user-assigned database_role for the session. + + :type logging_enabled: boolean + :param logging_enabled: (Optional) Represents whether the session pool + has logging enabled or not. Default is True """ def __init__( @@ -773,6 +802,7 @@ def __init__( ping_interval=3000, labels=None, database_role=None, + logging_enabled=True, ): """This throws a deprecation warning on initialization.""" warn( @@ -790,6 +820,7 @@ def __init__( ping_interval, labels=labels, database_role=database_role, + logging_enabled=logging_enabled, ) self.begin_pending_transactions() @@ -828,8 +859,7 @@ def put(self, session): # Stop background task for handling long running transactions if used sessions are less then threshold." if ( - self._database.close_inactive_transactions - or self._database.logging_enabled + self._database.close_inactive_transactions or self.logging_enabled ) and len( self._borrowed_sessions ) / self.size < self._used_sessions_ratio_threshold: diff --git a/tests/system/test_session_api.py b/tests/system/test_session_api.py index cc463b49ba..fe5e37f016 100644 --- a/tests/system/test_session_api.py +++ b/tests/system/test_session_api.py @@ -2536,7 +2536,6 @@ def test_should_close_inactive_transactions_with_bursty_pool_and_transaction( ddl_statements=_helpers.DDL_STATEMENTS, pool=pool, close_inactive_transactions=True, - logging_enabled=True, ) operation = temp_db.create() @@ -2585,7 +2584,6 @@ def test_should_close_inactive_transactions_with_fixedsize_pool_and_snapshot( database_name, pool=pool, close_inactive_transactions=True, - logging_enabled=True, ) with pytest.raises(Exception) as exc: @@ -2628,7 +2626,6 @@ def test_should_close_inactive_transactions_with_pinging_pool_and_batch( database_name, pool=pool, close_inactive_transactions=True, - logging_enabled=True, ) table = "contacts" diff --git a/tests/unit/spanner_dbapi/test_connect.py b/tests/unit/spanner_dbapi/test_connect.py index a847562926..f1c3b12ac8 100644 --- a/tests/unit/spanner_dbapi/test_connect.py +++ b/tests/unit/spanner_dbapi/test_connect.py @@ -56,7 +56,6 @@ def test_w_implicit(self, mock_client): instance.database.assert_called_once_with( DATABASE, pool=None, - logging_enabled=False, close_inactive_transactions=False, ) # Datbase constructs its own pool @@ -104,7 +103,6 @@ def test_w_explicit(self, mock_client): instance.database.assert_called_once_with( DATABASE, pool=pool, - logging_enabled=False, close_inactive_transactions=False, ) diff --git a/tests/unit/spanner_dbapi/test_connection.py b/tests/unit/spanner_dbapi/test_connection.py index fcddcd6864..37cfee4aad 100644 --- a/tests/unit/spanner_dbapi/test_connection.py +++ b/tests/unit/spanner_dbapi/test_connection.py @@ -19,6 +19,7 @@ import unittest import warnings import pytest +from google.cloud.spanner_v1 import BurstyPool PROJECT = "test-project" INSTANCE = "test-instance" @@ -1023,6 +1024,9 @@ def __init__( close_inactive_transactions=False, ): self.name = database_id - self.pool = pool + if pool is None: + pool = BurstyPool() + + self._pool = pool self.logging_enabled = logging_enabled self.close_inactive_transactions = close_inactive_transactions diff --git a/tests/unit/test_database.py b/tests/unit/test_database.py index 3961891480..a8a717b0aa 100644 --- a/tests/unit/test_database.py +++ b/tests/unit/test_database.py @@ -117,7 +117,6 @@ def test_ctor_defaults(self): self.assertTrue(database._pool._sessions.empty()) self.assertIsNone(database.database_role) self.assertTrue(database._route_to_leader_enabled, True) - self.assertTrue(database._logging_enabled) self.assertFalse(database._close_inactive_transactions) def test_ctor_w_explicit_pool(self): @@ -149,20 +148,6 @@ def test_ctor_w_route_to_leader_disbled(self): self.assertIs(database._instance, instance) self.assertFalse(database._route_to_leader_enabled) - def test_ctor_w_logger_enabled(self): - instance = _Instance(self.INSTANCE_NAME) - database = self._make_one(self.DATABASE_ID, instance, logging_enabled=True) - self.assertEqual(database.database_id, self.DATABASE_ID) - self.assertIs(database._instance, instance) - self.assertIs(database.logging_enabled, True) - - def test_ctor_w_logger_disabled(self): - instance = _Instance(self.INSTANCE_NAME) - database = self._make_one(self.DATABASE_ID, instance, logging_enabled=False) - self.assertEqual(database.database_id, self.DATABASE_ID) - self.assertIs(database._instance, instance) - self.assertIs(database.logging_enabled, False) - def test_ctor_w_close_inactive_transactions_enabled(self): instance = _Instance(self.INSTANCE_NAME) database = self._make_one( diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index a90813dcda..a3ccb51d18 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -48,14 +48,18 @@ def test_ctor_defaults(self): self.assertIsNone(pool._database) self.assertEqual(pool.labels, {}) self.assertIsNone(pool.database_role) + self.assertTrue(pool.logging_enabled) def test_ctor_explicit(self): labels = {"foo": "bar"} database_role = "dummy-role" - pool = self._make_one(labels=labels, database_role=database_role) + pool = self._make_one( + labels=labels, database_role=database_role, logging_enabled=False + ) self.assertIsNone(pool._database) self.assertEqual(pool.labels, labels) self.assertEqual(pool.database_role, database_role) + self.assertFalse(pool.logging_enabled) def test_bind_abstract(self): pool = self._make_one() @@ -176,7 +180,6 @@ def test_startCleaningLongRunningSessions_should_trigger_background_task_once( pool = self._make_one() pool._database = mock.MagicMock() - pool._database.logging_enabled = True pool._cleanup_task_ongoing_event.clear() with mock.patch( "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC", @@ -247,7 +250,7 @@ def put_side_effect(*args, **kwargs): pool.put.side_effect = put_side_effect - pool._database.logging_enabled = logging_enabled + pool.logging_enabled = logging_enabled pool._cleanup_task_ongoing_event.set() pool._database.close_inactive_transactions = close_inactive_transactions pool._borrowed_sessions = [] @@ -366,12 +369,17 @@ def test_ctor_defaults(self): self.assertTrue(pool._sessions.empty()) self.assertEqual(pool.labels, {}) self.assertIsNone(pool.database_role) + self.assertTrue(pool.logging_enabled) def test_ctor_explicit(self): labels = {"foo": "bar"} database_role = "dummy-role" pool = self._make_one( - size=4, default_timeout=30, labels=labels, database_role=database_role + size=4, + default_timeout=30, + labels=labels, + database_role=database_role, + logging_enabled=False, ) self.assertIsNone(pool._database) self.assertEqual(pool.size, 4) @@ -379,6 +387,7 @@ def test_ctor_explicit(self): self.assertTrue(pool._sessions.empty()) self.assertEqual(pool.labels, labels) self.assertEqual(pool.database_role, database_role) + self.assertFalse(pool.logging_enabled) def test_bind(self): database_role = "dummy-role" @@ -546,16 +555,23 @@ def test_ctor_defaults(self): self.assertTrue(pool._sessions.empty()) self.assertEqual(pool.labels, {}) self.assertIsNone(pool.database_role) + self.assertTrue(pool.logging_enabled) def test_ctor_explicit(self): labels = {"foo": "bar"} database_role = "dummy-role" - pool = self._make_one(target_size=4, labels=labels, database_role=database_role) + pool = self._make_one( + target_size=4, + labels=labels, + database_role=database_role, + logging_enabled=False, + ) self.assertIsNone(pool._database) self.assertEqual(pool.target_size, 4) self.assertTrue(pool._sessions.empty()) self.assertEqual(pool.labels, labels) self.assertEqual(pool.database_role, database_role) + self.assertFalse(pool.logging_enabled) def test_ctor_explicit_w_database_role_in_db(self): database_role = "dummy-role" @@ -690,6 +706,7 @@ def test_ctor_defaults(self): self.assertTrue(pool._sessions.empty()) self.assertEqual(pool.labels, {}) self.assertIsNone(pool.database_role) + self.assertTrue(pool.logging_enabled) def test_ctor_explicit(self): labels = {"foo": "bar"} @@ -700,6 +717,7 @@ def test_ctor_explicit(self): ping_interval=1800, labels=labels, database_role=database_role, + logging_enabled=False, ) self.assertIsNone(pool._database) self.assertEqual(pool.size, 4) @@ -708,6 +726,7 @@ def test_ctor_explicit(self): self.assertTrue(pool._sessions.empty()) self.assertEqual(pool.labels, labels) self.assertEqual(pool.database_role, database_role) + self.assertFalse(pool.logging_enabled) def test_ctor_explicit_w_database_role_in_db(self): database_role = "dummy-role" @@ -967,6 +986,7 @@ def test_ctor_defaults(self): self.assertTrue(pool._pending_sessions.empty()) self.assertEqual(pool.labels, {}) self.assertIsNone(pool.database_role) + self.assertTrue(pool.logging_enabled) def test_ctor_explicit(self): labels = {"foo": "bar"} @@ -977,6 +997,7 @@ def test_ctor_explicit(self): ping_interval=1800, labels=labels, database_role=database_role, + logging_enabled=False, ) self.assertIsNone(pool._database) self.assertEqual(pool.size, 4) @@ -986,6 +1007,7 @@ def test_ctor_explicit(self): self.assertTrue(pool._pending_sessions.empty()) self.assertEqual(pool.labels, labels) self.assertEqual(pool.database_role, database_role) + self.assertFalse(pool.logging_enabled) def test_ctor_explicit_w_database_role_in_db(self): database_role = "dummy-role" @@ -1269,7 +1291,6 @@ def __init__(self, name): self.database_id = name self._route_to_leader_enabled = True self.close_inactive_transactions = True - self.logging_enabled = True self._logger = mock.MagicMock() self._logger.info = mock.MagicMock() self._logger.warning = mock.MagicMock() From a75f147afe5102276b1f1cc2b5b0c6368cc6f63a Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Wed, 5 Jul 2023 10:47:48 +0530 Subject: [PATCH 21/24] review comments --- google/cloud/spanner_v1/database.py | 4 ++-- google/cloud/spanner_v1/pool.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index 84418d7b76..f8bb09b678 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -115,8 +115,8 @@ class Database(object): to stdout. :type close_inactive_transactions: boolean - :param close_inactive_transactions: (Optional) Represents whether the database - has close inactive transactions enabled or not. Default is False + :param close_inactive_transactions: (Optional) If set to True, the database will automatically close inactive transactions that have been running for longer than 60 minutes which may cause session leaks. + By default, this is set to False. :type encryption_config: :class:`~google.cloud.spanner_admin_database_v1.types.EncryptionConfig` diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index 8c701672ff..0e5c4b1838 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -281,7 +281,7 @@ def _close_long_running_transactions(self, session): if not session.transaction_logged: self._database.logger.warning( "Transaction has been running for longer than 60 minutes and might be causing a leak. " - + "Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions. " + + "Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions or use batch or partitioned transactions for long running operations." + session_trace ) session.transaction_logged = True From 9540c0a86b55a1ee37acac3f3f77d6ce63a7aeeb Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Mon, 24 Jul 2023 13:09:38 +0530 Subject: [PATCH 22/24] fix: long running error message --- google/cloud/spanner_v1/_helpers.py | 2 ++ google/cloud/spanner_v1/batch.py | 5 ++--- google/cloud/spanner_v1/pool.py | 5 ++--- google/cloud/spanner_v1/snapshot.py | 5 ++--- google/cloud/spanner_v1/transaction.py | 5 ++--- tests/system/test_session_api.py | 6 +++--- tests/unit/test_batch.py | 2 +- tests/unit/test_pool.py | 1 + tests/unit/test_snapshot.py | 6 +++--- tests/unit/test_transaction.py | 4 ++-- 10 files changed, 20 insertions(+), 21 deletions(-) diff --git a/google/cloud/spanner_v1/_helpers.py b/google/cloud/spanner_v1/_helpers.py index cf73e5c050..db0827c528 100644 --- a/google/cloud/spanner_v1/_helpers.py +++ b/google/cloud/spanner_v1/_helpers.py @@ -38,6 +38,8 @@ + "numeric has a whole component with precision {}" ) +LONG_RUNNING_TRANSACTION_ERR_MSG = "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML." + # Constants DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC = 120 DELETE_LONG_RUNNING_TRANSACTION_THRESHOLD_SEC = 3600 diff --git a/google/cloud/spanner_v1/batch.py b/google/cloud/spanner_v1/batch.py index dfd926ab4b..8cc0b37e21 100644 --- a/google/cloud/spanner_v1/batch.py +++ b/google/cloud/spanner_v1/batch.py @@ -29,6 +29,7 @@ from google.cloud.spanner_v1 import RequestOptions from google.cloud.spanner_v1._helpers import _retry from google.cloud.spanner_v1._helpers import _check_rst_stream_error +from google.cloud.spanner_v1._helpers import LONG_RUNNING_TRANSACTION_ERR_MSG from google.api_core.exceptions import InternalServerError @@ -145,9 +146,7 @@ def _check_state(self): if self.committed is not None: raise ValueError("Batch already committed") if self._session is None: - raise ValueError( - "Transaction has been closed as it was running for more than 60 minutes" - ) + raise ValueError(LONG_RUNNING_TRANSACTION_ERR_MSG) def commit(self, return_commit_stats=False, request_options=None): """Commit mutations to the database. diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index 0e5c4b1838..c7435d86ab 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -25,6 +25,7 @@ from google.cloud.spanner_v1._helpers import ( _metadata_with_prefix, _metadata_with_leader_aware_routing, + LONG_RUNNING_TRANSACTION_ERR_MSG, ) from warnings import warn @@ -263,9 +264,7 @@ def _close_long_running_transactions(self, session): if self.logging_enabled: # Log a warning for a long-running transaction that has been closed self._database.logger.warning( - "Long running transaction! Transaction has been closed as it was running for " - + "more than 60 minutes. For long running transactions use batch or partitioned transactions. " - + session_trace + LONG_RUNNING_TRANSACTION_ERR_MSG + session_trace ) # Set the session as None for associated transaction object diff --git a/google/cloud/spanner_v1/snapshot.py b/google/cloud/spanner_v1/snapshot.py index 8f8160be8c..8ffb30bf58 100644 --- a/google/cloud/spanner_v1/snapshot.py +++ b/google/cloud/spanner_v1/snapshot.py @@ -37,6 +37,7 @@ _retry, _check_rst_stream_error, _SessionWrapper, + LONG_RUNNING_TRANSACTION_ERR_MSG, ) from google.cloud.spanner_v1._opentelemetry_tracing import trace_call from google.cloud.spanner_v1.streamed import StreamedResultSet @@ -154,9 +155,7 @@ class _SnapshotBase(_SessionWrapper): def _check_session_state(self): if self._session is None: - raise ValueError( - "Transaction has been closed as it was running for more than 60 minutes" - ) + raise ValueError(LONG_RUNNING_TRANSACTION_ERR_MSG) def _make_txn_selector(self): """Helper for :meth:`read` / :meth:`execute_sql`. diff --git a/google/cloud/spanner_v1/transaction.py b/google/cloud/spanner_v1/transaction.py index de0b40f2f2..d61fb58603 100644 --- a/google/cloud/spanner_v1/transaction.py +++ b/google/cloud/spanner_v1/transaction.py @@ -24,6 +24,7 @@ _metadata_with_leader_aware_routing, _retry, _check_rst_stream_error, + LONG_RUNNING_TRANSACTION_ERR_MSG, ) from google.cloud.spanner_v1 import CommitRequest from google.cloud.spanner_v1 import ExecuteBatchDmlRequest @@ -64,9 +65,7 @@ def __init__(self, session): def _check_session_state(self): if self._session is None: - raise ValueError( - "Transaction has been closed as it was running for more than 60 minutes" - ) + raise ValueError(LONG_RUNNING_TRANSACTION_ERR_MSG) def _check_state(self): """Helper for :meth:`commit` et al. diff --git a/tests/system/test_session_api.py b/tests/system/test_session_api.py index fe5e37f016..d90b2180f7 100644 --- a/tests/system/test_session_api.py +++ b/tests/system/test_session_api.py @@ -2552,7 +2552,7 @@ def long_operation(transaction): temp_db.run_in_transaction(long_operation) assert ( exc.value.args[0] - == "Transaction has been closed as it was running for more than 60 minutes" + == "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML." ) @@ -2594,7 +2594,7 @@ def test_should_close_inactive_transactions_with_fixedsize_pool_and_snapshot( assert ( exc.value.args[0] - == "Transaction has been closed as it was running for more than 60 minutes" + == "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML." ) @@ -2645,7 +2645,7 @@ def test_should_close_inactive_transactions_with_pinging_pool_and_batch( assert ( exc.value.args[0] - == "Transaction has been closed as it was running for more than 60 minutes" + == "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML." ) diff --git a/tests/unit/test_batch.py b/tests/unit/test_batch.py index 7a4c921d47..532e0cda55 100644 --- a/tests/unit/test_batch.py +++ b/tests/unit/test_batch.py @@ -200,7 +200,7 @@ def test_commit_should_throw_error_for_recycled_session(self): batch.commit() self.assertEqual( str(cm.exception), - "Transaction has been closed as it was running for more than 60 minutes", + "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML.", ) def test_commit_grpc_error(self): diff --git a/tests/unit/test_pool.py b/tests/unit/test_pool.py index a3ccb51d18..4ff9d9a99e 100644 --- a/tests/unit/test_pool.py +++ b/tests/unit/test_pool.py @@ -147,6 +147,7 @@ def test_startCleaningLongRunningSessions_success(self, mock_thread_class): pool = self._make_one() pool._database = mock.MagicMock() pool._cleanup_task_ongoing_event.clear() + pool._cleanup_task_ongoing = False with mock.patch( "google.cloud.spanner_v1._helpers.DELETE_LONG_RUNNING_TRANSACTION_FREQUENCY_SEC", new=5, diff --git a/tests/unit/test_snapshot.py b/tests/unit/test_snapshot.py index c5131fdee2..d03d396039 100644 --- a/tests/unit/test_snapshot.py +++ b/tests/unit/test_snapshot.py @@ -825,7 +825,7 @@ def test_execute_sql_should_throw_error_for_recycled_session(self): self.assertEqual( str(cm.exception), - "Transaction has been closed as it was running for more than 60 minutes", + "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML.", ) def test_execute_sql_w_params_wo_param_types(self): @@ -1181,7 +1181,7 @@ def test_partition_read_should_throw_error_is_session_is_none(self): self.assertEqual( str(cm.exception), - "Transaction has been closed as it was running for more than 60 minutes", + "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML.", ) def test_partition_read_w_retry(self): @@ -1353,7 +1353,7 @@ def test_partition_query_should_throw_error_if_session_is_none(self): self.assertEqual( str(cm.exception), - "Transaction has been closed as it was running for more than 60 minutes", + "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML.", ) def test_partition_query_w_params_wo_param_types(self): diff --git a/tests/unit/test_transaction.py b/tests/unit/test_transaction.py index 2577431372..487344e2b5 100644 --- a/tests/unit/test_transaction.py +++ b/tests/unit/test_transaction.py @@ -314,7 +314,7 @@ def test_commit_should_throw_error_for_recycled_session(self): transaction.commit() self.assertEqual( str(cm.exception), - "Transaction has been closed as it was running for more than 60 minutes", + "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML.", ) def test_commit_already_committed(self): @@ -686,7 +686,7 @@ def test_batch_update_should_throw_error_for_recycled_session(self): transaction.batch_update(statements=[DML_QUERY]) self.assertEqual( str(cm.exception), - "Transaction has been closed as it was running for more than 60 minutes", + "Transaction has been closed as it was running for more than 60 minutes. If transaction is expected to run long, run as batch or partitioned DML.", ) def _batch_update_helper(self, error_after=None, count=0, request_options=None): From ee5b3a314398d0a9c9e4283dfbd14943f0752ae4 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Mon, 6 Nov 2023 13:50:44 +0530 Subject: [PATCH 23/24] race condition-session already returned to pool --- google/cloud/spanner_v1/pool.py | 52 ++++++++++++++++----------------- 1 file changed, 26 insertions(+), 26 deletions(-) diff --git a/google/cloud/spanner_v1/pool.py b/google/cloud/spanner_v1/pool.py index c7435d86ab..c61a4feb57 100644 --- a/google/cloud/spanner_v1/pool.py +++ b/google/cloud/spanner_v1/pool.py @@ -259,32 +259,32 @@ def _close_long_running_transactions(self, session): :returns: True if transaction is closed else False. """ session_recycled = False - session_trace = self._traces[session._session_id] - if self._database.close_inactive_transactions: - if self.logging_enabled: - # Log a warning for a long-running transaction that has been closed - self._database.logger.warning( - LONG_RUNNING_TRANSACTION_ERR_MSG + session_trace - ) - - # Set the session as None for associated transaction object - if session._transaction is not None: - session._transaction._session = None - - # Increment the count of closed transactions and return the session to the pool - session_recycled = True - self.put(session) - elif self.logging_enabled: - # Log a warning for a potentially leaking long-running transaction. - # Only log the warning if it hasn't been logged already. - if not session.transaction_logged: - self._database.logger.warning( - "Transaction has been running for longer than 60 minutes and might be causing a leak. " - + "Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions or use batch or partitioned transactions for long running operations." - + session_trace - ) - session.transaction_logged = True - + if session._session_id in self._traces: + session_trace = self._traces[session._session_id] + if self._database.close_inactive_transactions: + if self.logging_enabled: + # Log a warning for a long-running transaction that has been closed + self._database.logger.warning( + LONG_RUNNING_TRANSACTION_ERR_MSG + session_trace + ) + + # Set the session as None for associated transaction object + if session._transaction is not None: + session._transaction._session = None + + # Increment the count of closed transactions and return the session to the pool + session_recycled = True + self.put(session) + elif self.logging_enabled: + # Log a warning for a potentially leaking long-running transaction. + # Only log the warning if it hasn't been logged already. + if not session.transaction_logged: + self._database.logger.warning( + "Transaction has been running for longer than 60 minutes and might be causing a leak. " + + "Enable closeInactiveTransactions in Session Pool Options to automatically clean such transactions or use batch or partitioned transactions for long running operations." + + session_trace + ) + session.transaction_logged = True return session_recycled From 9331df2bfe27d8c39f5cbe9786d834f6dedf3b41 Mon Sep 17 00:00:00 2001 From: surbhigarg92 Date: Mon, 6 Nov 2023 15:01:41 +0530 Subject: [PATCH 24/24] lint --- google/cloud/spanner_v1/database.py | 1 - 1 file changed, 1 deletion(-) diff --git a/google/cloud/spanner_v1/database.py b/google/cloud/spanner_v1/database.py index d5babb48ad..5f6dd75114 100644 --- a/google/cloud/spanner_v1/database.py +++ b/google/cloud/spanner_v1/database.py @@ -663,7 +663,6 @@ def execute_partitioned_dml( def execute_pdml(): with SessionCheckout(self._pool, isLongRunning=True) as session: - txn = api.begin_transaction( session=session.name, options=txn_options, metadata=metadata )