unexpected transaction start times with mssql temporal (system versioned) tables

[ManelBH]

Describe the bug

This is a duplicate of issue #5690 which I don't think was well understood. This doesn't happen using plain pyodbc so it all points to a SQLAlchemy issue, maybe related to how sessions are managed.

Context:

I'm using SQL server's system versioned tables. These tables automatically record the time of creation/modification and according to the documentation it's the time the transaction was started. After more investigation this seemingly refers to the outtermost transaction which in this case will be the implicit transaction opened by ODBC.

Problem:

As I create new sessions to update records in the system versioned table it records times from before the new session was created. The script below may help understand this.

Optional link from https://docs.sqlalchemy.org which documents the behavior that is expected

No response

SQLAlchemy Version in Use

2.0.30

DBAPI (i.e. the database driver)

pyodbc

Database Vendor and Major Version

SQL Server 12 (2014)

Python Version

3.10

Operating system

Windows

To Reproduce

Create a system versioned table and add a record to modify:

CREATE TABLE [dbo].[_TestTable](
	[Id] [int] IDENTITY(1,1) NOT NULL,
	[UserName] [nvarchar](50) NOT NULL,
	[StartTime] [datetime2](7) GENERATED ALWAYS AS ROW START NOT NULL,
	[EndTime] [datetime2](7) GENERATED ALWAYS AS ROW END NOT NULL,
PRIMARY KEY CLUSTERED 
(
	[Id] ASC
)WITH (STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, OPTIMIZE_FOR_SEQUENTIAL_KEY = OFF) ON [PRIMARY],
	PERIOD FOR SYSTEM_TIME ([StartTime], [EndTime])
) ON [PRIMARY]
WITH
(
SYSTEM_VERSIONING = ON ( HISTORY_TABLE = [dbo].[_TestTableHistory] )
)
GO

INSERT INTO dbo.[_TestTable] (UserName) VALUES('John')
GO

Run the following script:

from typing import List
from time import sleep
from datetime import datetime, timezone

from sqlalchemy import create_engine, text
from sqlalchemy.orm import sessionmaker
from sqlalchemy.engine import URL
import pyodbc


def format_time(time: datetime) -> str:
    return time.strftime("%H:%M:%S.%f")


CONNECTION_STRING = "<your_connection_string>"

connection_url = URL.create("mssql+pyodbc", query={"odbc_connect": CONNECTION_STRING})
engine = create_engine(connection_url)
SessionLocal = sessionmaker(autocommit=False, autoflush=False, bind=engine)

commitTimes: List[datetime] = []
sqlTimes: List[datetime] = []

print("SQLAlchemy Behaviour:")
with SessionLocal() as db:
    cmd = text("UPDATE [dbo].[_TestTable] SET UserName=:name WHERE Id=:id")
    cmd = cmd.bindparams(name='foo', id=1)
    db.execute(cmd)
    db.commit()
    commitTimes.append(datetime.now(timezone.utc))

    query = text("SELECT [StartTime] FROM [dbo].[_TestTable] WHERE Id=1")
    result = db.execute(query)
    row = result.fetchone()
    sqlTimes.append(row[0])


sleep(10)
with SessionLocal() as db:
    cmd = text("UPDATE [dbo].[_TestTable] SET UserName=:name WHERE Id=:id")
    cmd = cmd.bindparams(name='bar', id=1)
    db.execute(cmd)
    db.commit()
    commitTimes.append(datetime.now(timezone.utc))

    query = text("SELECT [StartTime] FROM [dbo].[_TestTable] WHERE Id=1")
    result = db.execute(query)
    row = result.fetchone()
    sqlTimes.append(row[0])

print(f"{'First commit:':<15} {format_time(commitTimes[0])}")
print(f"{'First save:':<15} {format_time(sqlTimes[0])}")
print(f"{'Second commit:':<15} {format_time(commitTimes[1])}")
print(f"{'Second save:':<15} {format_time(sqlTimes[1])}")

commitTimes.clear()
sqlTimes.clear()
print()

print("Expected Behaviour (pyodbc):")
with pyodbc.connect(CONNECTION_STRING, autocommit=False) as conn:
    with conn.cursor() as cursor:
        cursor.execute("UPDATE [dbo].[_TestTable] SET UserName=? WHERE Id=?", 'foo', 1)
        conn.commit()
        commitTimes.append(datetime.now(timezone.utc))

        cursor.execute("SELECT [StartTime] FROM [dbo].[_TestTable] WHERE Id=1")
        row = cursor.fetchone()
        sqlTimes.append(row[0])

sleep(10)
with pyodbc.connect(CONNECTION_STRING, autocommit=False) as conn:
    with conn.cursor() as cursor:
        cursor.execute("UPDATE [dbo].[_TestTable] SET UserName=? WHERE Id=?", 'bar', 1)
        conn.commit()
        commitTimes.append(datetime.now(timezone.utc))

        cursor.execute("SELECT [StartTime] FROM [dbo].[_TestTable] WHERE Id=1")
        row = cursor.fetchone()
        sqlTimes.append(row[0])

print(f"{'First commit:':<15} {format_time(commitTimes[0])}")
print(f"{'First save:':<15} {format_time(sqlTimes[0])}")
print(f"{'Second commit:':<15} {format_time(commitTimes[1])}")
print(f"{'Second save:':<15} {format_time(sqlTimes[1])}")

Error

The script will print something like this:

SQLAlchemy Behaviour:
First commit: 11:20:21.180088
First save: 11:20:20.997437
Second commit: 11:20:31.521453
Second save: 11:20:21.294313

Expected Behaviour (pyodbc):
First commit: 11:20:32.385461
First save: 11:20:32.231844
Second commit: 11:20:43.322678
Second save: 11:20:43.122553

Expected/Actual behaviour

Notice how in the expected behaviour sample the save time is always a few miliseconds before the respective commit time, which makes sense as this is the time from when the transaction was opened.

In the SQLAlchemy sample instead the second save time is shortly after the first commit, way before the second session is even created. It looks as if SQLAlchemy is keeping the old transaction in between sessions.

Additional context

No response

[ManelBH]

In the meantime I'd appreciate a workaround as this is making our system-versioned tables unusable.

[zzzeek]

hi -

I see in issue #5690 there was no reproducer created, in this case you've provided a script, thanks for that. However the claim that SQLAlchemy is holding open a transaction is definitely not the case, so we would assume this is some artifact of connection pooling - that is, your "pyodbc" example uses two separate connections, whereas your SQLAlchemy example will use the same connection by default. We would then make a random guess that something about pyodbc / system versioned tables etc. is producing this behavior (which to be honest I haven't walked through to understand exactly what the problem is, since this looks like driver behaviors).

Try turning off pooling:

from sqlalchemy.pool import NullPool
engine = create_engine(connection_url, poolclass=NullPool)

the sequence of connection usage should then be mostly identical to your pyodbc version.

cc @gordthompson

[zzzeek]

also if i were to run this script I'd want to change this:

commitTimes.append(datetime.now(timezone.utc))

since you can't assume arbitrary test environments will report the same system time on the client Python interpreter vs the database server.

my own env here they seem to be close to within a millisecond, which is good enough

import datetime

from sqlalchemy import Column
from sqlalchemy import create_engine
from sqlalchemy import DateTime
from sqlalchemy import func
from sqlalchemy import Integer
from sqlalchemy.orm import declarative_base
from sqlalchemy.orm import Session

Base = declarative_base()


class A(Base):
    __tablename__ = 'a'

    id = Column(Integer, primary_key=True)
    server_data = Column(DateTime, default=func.now())
    client_data = Column(DateTime, default=datetime.datetime.now)


e = create_engine("postgresql://scott:tiger@localhost/test", echo=True)
Base.metadata.drop_all(e)
Base.metadata.create_all(e)

s = Session(e)

a1 = A()
s.add(a1)
s.commit()

print(f"Server time: {a1.server_data}\nClient time: {a1.client_data}")

Server time: 2024-06-03 08:43:44.975425
Client time: 2024-06-03 08:43:44.975317

[zzzeek]

also , can't drop these tables. here are the steps

    conn.exec_driver_sql("""
        ALTER TABLE [dbo].[_TestTable] SET ( SYSTEM_VERSIONING = OFF)
    """)

    conn.exec_driver_sql("""DROP TABLE [dbo].[_TestTable]""")
    conn.exec_driver_sql("""DROP TABLE [dbo].[_TestTableHistory]""")

[zzzeek]

another thing of note, your pyodbc version is using the same cursor across transactions. this seems to create problems, in my "pyodbc-only" reproducer I will fix that also

[zzzeek]

Here's the same behavior with pyodbc directly, so the problem is in pyodbc and I would report this issue to them. You can use a new connection each time by using NullPool as mentioned above

from typing import List
from time import sleep
from datetime import datetime, timezone

import pyodbc


def format_time(time: datetime) -> str:
    return time.strftime("%H:%M:%S.%f")


commitTimes: List[datetime] = []
sqlTimes: List[datetime] = []

connect_string = 'DRIVER={ODBC Driver 18 for SQL Server};Server=mssql2022,1433;Database=test;UID=scott;PWD=tiger^5HHH;TrustServerCertificate=yes;Encrypt=Optional'
print("The buggy behavior with pyodbc directly:")

# autocommit=False does not seem to matter (note SQLAlhcemy version is not setting this
# unless you add an appropriate isolation_level setting)
pyodbc_conn = pyodbc.connect(connect_string, autocommit=False)

with pyodbc_conn.cursor() as cursor:
    cursor.execute("UPDATE [_TestTable] SET UserName=? WHERE Id=?", 'foo', 1)
pyodbc_conn.commit()
commitTimes.append(datetime.now(timezone.utc))

with pyodbc_conn.cursor() as cursor:
    cursor.execute("SELECT [StartTime] FROM [_TestTable] WHERE Id=1")
    row = cursor.fetchone()
    sqlTimes.append(row[0])
pyodbc_conn.rollback()

sleep(10)

# uncomment to "fix"
# pyodbc_conn = pyodbc.connect(connect_string)

with pyodbc_conn.cursor() as cursor:
    cursor.execute("UPDATE [_TestTable] SET UserName=? WHERE Id=?", 'bar', 1)
pyodbc_conn.commit()
commitTimes.append(datetime.now(timezone.utc))

with pyodbc_conn.cursor() as cursor:
    cursor.execute("SELECT [StartTime] FROM [_TestTable] WHERE Id=1")
    row = cursor.fetchone()
    sqlTimes.append(row[0])
pyodbc_conn.rollback()



print(f"{'First commit:':<15} {format_time(commitTimes[0])}")
print(f"{'First save:':<15} {format_time(sqlTimes[0])}")
print(f"{'Second commit:':<15} {format_time(commitTimes[1])}")
print(f"{'Second save:':<15} {format_time(sqlTimes[1])}")```

output, without the "fix"

The buggy behavior with pyodbc directly:
First commit:   13:05:43.470174
First save:     13:05:43.439485
Second commit:  13:05:53.491214
Second save:    13:05:43.472502

for my own reference, below is my full original script that includes DDL plus all three versions

from typing import List
from time import sleep
from datetime import datetime, timezone

from sqlalchemy import create_engine, text
from sqlalchemy.orm import sessionmaker
from sqlalchemy.engine import URL
from sqlalchemy.pool import NullPool
import pyodbc


def format_time(time: datetime) -> str:
    return time.strftime("%H:%M:%S.%f")

CONNECTION_STRING= "DRIVER={ODBC Driver 18 for SQL Server};Server=mssql2022,1433;Database=test;UID=scott;PWD=tiger^5HHH;TrustServerCertificate=yes;Encrypt=Optional"
connection_url = URL.create("mssql+pyodbc", query={"odbc_connect": CONNECTION_STRING})
engine = create_engine(connection_url,
    echo=True,

    # uncomment to "fix"
    poolclass=NullPool
)


with engine.begin() as conn:
    conn.exec_driver_sql("""
        ALTER TABLE [dbo].[_TestTable] SET ( SYSTEM_VERSIONING = OFF)
    """)

    conn.exec_driver_sql("""DROP TABLE [dbo].[_TestTable]""")
    conn.exec_driver_sql("""DROP TABLE [dbo].[_TestTableHistory]""")

    conn.exec_driver_sql("""
CREATE TABLE [dbo].[_TestTable](
	[Id] [int] IDENTITY(1,1) NOT NULL,
	[UserName] [nvarchar](50) NOT NULL,
	[StartTime] [datetime2](7) GENERATED ALWAYS AS ROW START NOT NULL,
	[EndTime] [datetime2](7) GENERATED ALWAYS AS ROW END NOT NULL,
PRIMARY KEY CLUSTERED
(
	[Id] ASC
)WITH (STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, OPTIMIZE_FOR_SEQUENTIAL_KEY = OFF) ON [PRIMARY],
	PERIOD FOR SYSTEM_TIME ([StartTime], [EndTime])
) ON [PRIMARY]
WITH
(
SYSTEM_VERSIONING = ON ( HISTORY_TABLE = [dbo].[_TestTableHistory] )
)
""")


    conn.exec_driver_sql("""INSERT INTO dbo.[_TestTable] (UserName) VALUES('John')""")


SessionLocal = sessionmaker(autocommit=False, autoflush=False, bind=engine)

commitTimes: List[datetime] = []
sqlTimes: List[datetime] = []

print("SQLAlchemy Behaviour:")
with SessionLocal() as db:
    cmd = text("UPDATE [_TestTable] SET UserName=:name WHERE Id=:id")
    cmd = cmd.bindparams(name='foo', id=1)
    db.execute(cmd)
    db.commit()
    commitTimes.append(datetime.now(timezone.utc))

    query = text("SELECT [StartTime] FROM [_TestTable] WHERE Id=1")
    result = db.execute(query)
    row = result.fetchone()
    sqlTimes.append(row[0])


sleep(10)
with SessionLocal() as db:
    cmd = text("UPDATE [_TestTable] SET UserName=:name WHERE Id=:id")
    cmd = cmd.bindparams(name='bar', id=1)
    db.execute(cmd)
    db.commit()
    commitTimes.append(datetime.now(timezone.utc))

    query = text("SELECT [StartTime] FROM [_TestTable] WHERE Id=1")
    result = db.execute(query)
    row = result.fetchone()
    sqlTimes.append(row[0])

print(f"{'First commit:':<15} {format_time(commitTimes[0])}")
print(f"{'First save:':<15} {format_time(sqlTimes[0])}")
print(f"{'Second commit:':<15} {format_time(commitTimes[1])}")
print(f"{'Second save:':<15} {format_time(sqlTimes[1])}")

commitTimes.clear()
sqlTimes.clear()
print()

print("Expected Behaviour (pyodbc):")
with pyodbc.connect(CONNECTION_STRING, autocommit=False) as conn:
    with conn.cursor() as cursor:
        cursor.execute("UPDATE [_TestTable] SET UserName=? WHERE Id=?", 'foo', 1)
        conn.commit()
        commitTimes.append(datetime.now(timezone.utc))

        cursor.execute("SELECT [StartTime] FROM [_TestTable] WHERE Id=1")
        row = cursor.fetchone()
        sqlTimes.append(row[0])

sleep(10)
with pyodbc.connect(CONNECTION_STRING, autocommit=False) as conn:
    with conn.cursor() as cursor:
        cursor.execute("UPDATE [_TestTable] SET UserName=? WHERE Id=?", 'bar', 1)
        conn.commit()
        commitTimes.append(datetime.now(timezone.utc))

        cursor.execute("SELECT [StartTime] FROM [_TestTable] WHERE Id=1")
        row = cursor.fetchone()
        sqlTimes.append(row[0])

# shouldn't conn be closed already??  script below fails if we dont
# do this first
conn.close()

print(f"{'First commit:':<15} {format_time(commitTimes[0])}")
print(f"{'First save:':<15} {format_time(sqlTimes[0])}")
print(f"{'Second commit:':<15} {format_time(commitTimes[1])}")
print(f"{'Second save:':<15} {format_time(sqlTimes[1])}")

commitTimes.clear()
sqlTimes.clear()
print()


print("The buggy behavior with pyodbc directly:")

pyodbc_conn = pyodbc.connect(CONNECTION_STRING, autocommit=False)
with pyodbc_conn.cursor() as cursor:
    cursor.execute("UPDATE [_TestTable] SET UserName=? WHERE Id=?", 'foo', 1)
pyodbc_conn.commit()
commitTimes.append(datetime.now(timezone.utc))

with pyodbc_conn.cursor() as cursor:
    cursor.execute("SELECT [StartTime] FROM [_TestTable] WHERE Id=1")
    row = cursor.fetchone()
    sqlTimes.append(row[0])
pyodbc_conn.rollback()

sleep(10)

# uncomment to "fix"
# pyodbc_conn = pyodbc.connect(connect_string, autocommit=False)

with pyodbc_conn.cursor() as cursor:
    cursor.execute("UPDATE [_TestTable] SET UserName=? WHERE Id=?", 'bar', 1)
pyodbc_conn.commit()
commitTimes.append(datetime.now(timezone.utc))

with pyodbc_conn.cursor() as cursor:
    cursor.execute("SELECT [StartTime] FROM [_TestTable] WHERE Id=1")
    row = cursor.fetchone()
    sqlTimes.append(row[0])
pyodbc_conn.rollback()



print(f"{'First commit:':<15} {format_time(commitTimes[0])}")
print(f"{'First save:':<15} {format_time(sqlTimes[0])}")
print(f"{'Second commit:':<15} {format_time(commitTimes[1])}")
print(f"{'Second save:':<15} {format_time(sqlTimes[1])}")

[CaselIT]

Now I'm convinced my assumption was wrong and it has nothing to do with transactions. It rather looks like the versioned tables might be using the connection time

This seems strange, and would contradict the log of your initial example. If the time used by sqlserver is the connection time, I would expect First save and Second save to have the same value. It appears that Second save is instead just after the first commit.

The behaviour is not clear, so if using nullpool does not have adverse performance effect that's likely the safest option

[ManelBH]

This seems strange, and would contradict the log of your initial example. If the time used by sqlserver is the connection time, I would expect First save and Second save to have the same value. It appears that Second save is instead just after the first commit.

You're right, indeed after updating multiple times it's always some instant after the last commit, turns out there's a more simple explanation which is that commit/rollback don't do anything if there are no pending statements.

[CaselIT]

that may be the case, but it would be very poor design to ignore commit/rollback if there are no pending statements since there are still things that may happen at the end/start of a transaction, see here the save of the start-transaction-time.

Maybe adding a select 1 then rollback would work around that?
Overall seems very messy. NullPool when using this feature seems a vastly safer option

[ManelBH]

That's more or less what I tried, executing a variable declaration and then calling commit/rollback works.
But yeah for now I'll rather stick with the NullPool.

[gordthompson]

Maybe adding a select 1 then rollback would work around that?

That might still be a useful workaround for people

• using mssql+pymssql, or
• using mssql+pyodbc on non-Windows platforms where unixODBC connection pooling is off by default (and Nick says that connection pooling doesn't work with Python anyway).

[CaselIT]

@zzzeek instead of a nullpool maybe it's enough to just add a https://docs.sqlalchemy.org/en/20/core/events.html#sqlalchemy.events.PoolEvents.checkout event to execute a rollback/commit to reset the transaction?

@event.listens_for(engine , 'checkout')
def receive_checkout(dbapi_connection, connection_record, connection_proxy):
  dbapi_connection.rollback()  # commit should work too

It seems that pyodbc starts a new transaction on the server as soon as commit / rollback is executed.

[CaselIT]

the pool already calls rollback(). im not able to make the problem go away on a single pyodbc connection period.

If I don't remember wrongly that's on checkin. The event is on checkout, meaning that I'm suggestion to call rollback (of commit) when taking out a connection from the pool

[zzzeek]

It would be super duper wrong for an idle pyodbc connection that just had the transaction ended to be automatically opened in a new transaction when nothing occurred to start one. The DBAPI model is that begin happens when sql is first emitted on a cursor.

[CaselIT]

I agree, but that's what seem to happen in the first message, in ethe error output #11444 (comment)

The save time seems to be just after the commit was called.

[gordthompson]

It would be super duper wrong for an idle pyodbc connection that just had the transaction ended to be automatically opened in a new transaction when nothing occurred to start one. The DBAPI model is that begin happens when sql is first emitted on a cursor.

Hmmm, PEP 249 doesn't appear to say anything about that one way or the other, In any case, pymssql also seems to start a new transaction immediately after the commit. Using my SQLAlchemy example above with pymssql instead of pyodbc, SQL Profiler shows

EventClass          TextData                               ApplicationName  SPID  StartTime            EndTime            
------------------  -------------------------------------  ---------------  ----  -------------------  -------------------
SQL:BatchStarting   UPDATE t SET txt = 'foo' WHERE id = 1  pymssql=2.3.0      53  2024-06-03 22:11:55                     
SQL:BatchCompleted  UPDATE t SET txt = 'foo' WHERE id = 1  pymssql=2.3.0      53  2024-06-03 22:11:55  2024-06-03 22:11:55
SQL:BatchStarting   COMMIT TRAN                            pymssql=2.3.0      53  2024-06-03 22:12:01                     
SQL:BatchCompleted  COMMIT TRAN                            pymssql=2.3.0      53  2024-06-03 22:12:01  2024-06-03 22:12:01
SQL:BatchStarting   BEGIN TRAN                             pymssql=2.3.0      53  2024-06-03 22:12:01                     
SQL:BatchCompleted  BEGIN TRAN                             pymssql=2.3.0      53  2024-06-03 22:12:01  2024-06-03 22:12:01

[zzzeek]

well, that's pretty wrong!

[gordthompson]

Summary

TL;DR - If Windows' own connection pooling is active (which it is by default for Microsoft's "ODBC Driver nn for Windows") then using NullPool for the SQLAlchemy pool is the best solution.

With autocommit=False (the DBAPI default), .commit() or .rollback() causes ODBC to end the current transaction and immediately start a new one.

With SQLAlchemy's default QueuePool, when a SQLAlchemy connection is "closed" the DBAPI connection is not closed, it is just returned to SQLAlchemy's connection pool. When that connection is checked out of the QueuePool .connect() is not called again and it still has the old transaction from when it was checked in.

With NullPool, closing the SQLAlchemy connection also closes the DBAPI connection. However, that connection is still in Windows' connection pool. The next time SQLAlchemy "creates" a DBAPI connection via pyodbc.connect(), the connection in Windows' connection pool is retrieved and a new transaction is started. So we're still getting pooled connections, just at the Windows level instead of the SQLAlchemy level.

[CaselIT]

strange that doing something like this #11444 (comment) does not force the creation of a new transaction (or at least it appeared not from what the OP said, I haven't tried it)

[gordthompson]

It appears that a rollback on a transaction that isn't dirty is treated as a no-op. :(

[CaselIT]

that's really quite a foot-gun..

[gordthompson]

strange that doing something like this #11444 (comment) does not force the creation of a new transaction (or at least it appeared not from what the OP said, I haven't tried it)

That doesn't solve the problem, but this appears to do the trick for mssql+pyodbc:

@event.listens_for(engine , 'checkout')
def receive_checkout(dbapi_connection, connection_record, connection_proxy):
    dbapi_connection.execute("SELECT 1")
    dbapi_connection.rollback()  # commit works, too

For mssql+pymssql:

@event.listens_for(engine , 'checkout')
def receive_checkout(dbapi_connection, connection_record, connection_proxy):
    crsr = dbapi_connection.cursor()
    crsr.execute("SELECT 1")
    dbapi_connection.rollback()  # commit works, too