coruble
coruble

Reputation: 21

Why are open transactions showing up in SQL Server on idle sessions when I use a SQL Alchemy Engine and connection pooling to connect from Python?

I have a web application built with Python and Flask, and I'm trying to use SQL Alchemy to manage connection pooling for my connections to SQL Server. Since implementing this, we had an event where our SQL Server maxed out on memory and a bunch of applications and data-refreshes across our company crashed--so now we're very seriously looking into whether the connection pooling setup led to this overload.

I've found that once I execute a transaction with my SQL Alchemy Engine, it creates a persistent session on the SQL Server--which seems to be the desired behavior. However, the session also has a persistent open transaction--which is not the expected behavior.

I believe I'm following the best practices for transaction management in the documentation, and I can see in the pool.echo logging that the transaction is committed at the end of the engine.begin() block.

import sqlalchemy as sa

conn_string = "DRIVER={ODBC Driver 18 for SQL Server};SERVER=<serverAddress>,<port>;DATABASE=<myDB>;UID=<myUID>;PWD=<myPass>;Encrypt=yes;TrustServerCertificate=yes;Connection Timeout=10"

engine = sa.create_engine(f"mssql+pyodbc:///?odbc_connect={conn_string}"
                                  , echo_pool=True
                                  , echo=True)

with engine.begin() as conn:
    result = conn.execute(sa.text("select top 1 * from SomeTable"))
    print(result.all())

This yields the following echo logging lines:

2025-01-15 09:47:49,391 INFO sqlalchemy.engine.Engine SELECT CAST(SERVERPROPERTY('ProductVersion') AS VARCHAR)
2025-01-15 09:47:49,393 INFO sqlalchemy.engine.Engine [raw sql] ()
2025-01-15 09:47:49,428 INFO sqlalchemy.engine.Engine SELECT schema_name()
2025-01-15 09:47:49,429 INFO sqlalchemy.engine.Engine [generated in 0.00088s] ()
2025-01-15 09:47:49,531 INFO sqlalchemy.engine.Engine SELECT CAST('test max support' AS NVARCHAR(max))
2025-01-15 09:47:49,532 INFO sqlalchemy.engine.Engine [generated in 0.00140s] ()
2025-01-15 09:47:49,563 INFO sqlalchemy.engine.Engine SELECT 1 FROM fn_listextendedproperty(default, default, default, default, default, default, default)
2025-01-15 09:47:49,565 INFO sqlalchemy.engine.Engine [generated in 0.00120s] ()
2025-01-15 09:47:49,624 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2025-01-15 09:47:49,626 INFO sqlalchemy.engine.Engine select top 1 * from SomeTable
2025-01-15 09:47:49,627 INFO sqlalchemy.engine.Engine [generated in 0.00135s] ()
[(1,)]
2025-01-15 09:47:49,660 INFO sqlalchemy.engine.Engine COMMIT

My understanding is that the last logging line with "COMMIT" is committing the transaction (which is read only in this case, but other times could be a write transaction). However, when I check the active sessions on SQL Server, I see the sleeping session with 1 open transaction.

SELECT s.session_id, s.status, s.transaction_isolation_level, s.open_transaction_count,
       st.transaction_id, s.row_count, s.login_time, s.last_request_start_time, 
       s.last_request_end_time, s.client_version, s.client_interface_name
FROM sys.dm_exec_sessions AS s
JOIN sys.dm_tran_session_transactions st ON st.session_id = s.session_id
WHERE login_name='myUID' AND host_name='myHost'
       AND EXISTS (
               SELECT *
               FROM sys.dm_tran_session_transactions AS t
               WHERE t.session_id = s.session_id
           )
           AND NOT EXISTS (
               SELECT *
               FROM sys.dm_exec_requests AS r
               WHERE r.session_id = s.session_id
           )

SQL Query result showing sleeping session with open transaction

My colleagues think this is an orphaned transaction, and that those are the root cause of our server slow-downs/overload event. I'm not sure--I think this may simply be the way that SQL Alchemy implements the connection pool, and that the slowdown may have been caused by having too many of these connections open across our many deployment environments, where there end up being many pools across separate environments.

My questions are 3-fold:

  1. Does anyone have some insight on what's going on here?
  2. Are these apparently orphaned transactions normal/to be expected?
  3. Am I doing something wrong in my configuration or use that's leading to orphaned transactions?

Here's my tech stack:

Flask==2.2.5
pyodbc==5.2.0
sqlalchemy==2.0.37
python==3.11.7

Experiments and Findings

  1. I noticed if I use the engine to run another query, a new transaction id shows up in sys.dm_tran_session_transactions, and the open_transaction count on the session remains at 1. This is another point that makes me believe this may just be the way SQL Alchemy handles the QueuePool connection.
with engine.begin() as conn:
    result = conn.execute(sa.text("select top 1 * from SchemaChangeHistory"))
    print(result.all())
2025-01-15 10:20:13,821 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2025-01-15 10:20:13,822 INFO sqlalchemy.engine.Engine select top 1 * from SchemaChangeHistory
2025-01-15 10:20:13,823 INFO sqlalchemy.engine.Engine [cached since 1944s ago] ()
[(1,)]
2025-01-15 10:20:13,905 INFO sqlalchemy.engine.Engine COMMIT

SQL Query result showing the same sleeping session with 1 open transaction, but now a new transaction ID

  1. Running engine.dispose() after using the engine clears out the session with the open transaction. I could run this after each execution, but wouldn't that defeat the purpose of connection pooling?
2025-01-15 10:24:49,344 INFO sqlalchemy.pool.impl.QueuePool Pool disposed. Pool size: 5  Connections in pool: 0 Current Overflow: -5 Current Checked out connections: 0
2025-01-15 10:24:49,345 INFO sqlalchemy.pool.impl.QueuePool Pool recreating

An empty session query result set

  1. Using the NullPool option yields different results: no lingering open sessions with open transactions. My fallback plan is just to go back to using this, but I would love to get connection pooling set up and working well so we can enjoy those benefits.
import sqlalchemy as sa

engine = sa.create_engine(f"mssql+pyodbc:///?odbc_connect={os.environ.get('SQLCONNSTR_pe_DW')}"
                                  , echo_pool=True
                                  , echo=True
                                  , poolclass=sa.pool.NullPool)

with engine.begin() as conn:
    result = conn.execute(sa.text("select top 1 * from SchemaChangeHistory"))
    print(result.all())
2025-01-15 10:32:35,261 INFO sqlalchemy.engine.Engine SELECT CAST(SERVERPROPERTY('ProductVersion') AS VARCHAR)
2025-01-15 10:32:35,262 INFO sqlalchemy.engine.Engine [raw sql] ()
2025-01-15 10:32:35,296 INFO sqlalchemy.engine.Engine SELECT schema_name()
2025-01-15 10:32:35,298 INFO sqlalchemy.engine.Engine [generated in 0.00267s] ()
2025-01-15 10:32:35,398 INFO sqlalchemy.engine.Engine SELECT CAST('test max support' AS NVARCHAR(max))
2025-01-15 10:32:35,400 INFO sqlalchemy.engine.Engine [generated in 0.00206s] ()
2025-01-15 10:32:35,432 INFO sqlalchemy.engine.Engine SELECT 1 FROM fn_listextendedproperty(default, default, default, default, default, default, default)
2025-01-15 10:32:35,434 INFO sqlalchemy.engine.Engine [generated in 0.00239s] ()
2025-01-15 10:32:35,500 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2025-01-15 10:32:35,502 INFO sqlalchemy.engine.Engine select top 1 * from SomeTable
2025-01-15 10:32:35,503 INFO sqlalchemy.engine.Engine [generated in 0.00152s] ()
[(1,)]
2025-01-15 10:32:35,748 INFO sqlalchemy.engine.Engine COMMIT

An empty session query result set

Proposed Path Forward:

Either

  1. Use NullPool as the pool class to wash my hands of all this (lol), or
  2. Thoughtfully implement the pool_recyle and pool_use_lifo parameters to finetune the lifetime of my connection pools, ensuring there aren't lingering connections when they're not needed.

Upvotes: 1

Views: 73

Answers (1)

Ian Wilson
Ian Wilson

Reputation: 9089

Leaving open connections is the point of the pooling but leaving open transactions seems totally broken to me. The connection should be reset when it is returned to the pool: https://docs.sqlalchemy.org/en/20/core/pooling.html#reset-on-return

Maybe turn on pool logging as seen here: https://docs.sqlalchemy.org/en/20/core/pooling.html#logging-reset-on-return-events

Also I saw this but I'm not sure it affects you:

https://docs.sqlalchemy.org/en/20/dialects/mssql.html#mssql-reset-on-return

Upvotes: 1

Related Questions