SQL Server System Versioned Table Execution Timing

sql serversql-server-2017temporal-tables

I am trying to learn more about system versioned tables in SQL Server so I am running a script to perform simple DML statements on a system versioned table and capturing different times stamps that are used for inspecting the tables between each statement.

Setup

IF  EXISTS (SELECT * FROM sys.objects WHERE object_id = OBJECT_ID(N'[dbo].[EXAMPLE_TABLE]') AND type in (N'U'))
ALTER TABLE [dbo].[EXAMPLE_TABLE] SET ( SYSTEM_VERSIONING = OFF  )
GO
DROP TABLE IF EXISTS [dbo].[EXAMPLE_TABLE]
GO
DROP TABLE IF EXISTS [dbo].[EXAMPLE_TABLE_HISTORY]
GO

CREATE TABLE dbo.EXAMPLE_TABLE_HISTORY (
    ID INT NOT NULL,
    -- 'data'
    ColA VARCHAR(255) NULL,
    ColB VARCHAR(255) NULL,
    ColC VARCHAR(255) NULL,
    SysStartTime DATETIME2 NOT NULL,
    SysEndTime DATETIME2 NOT NULL
);
CREATE CLUSTERED INDEX IX_EXAMPLE_TABLE_HISTORY__SysEndTime_SysStartTime
    ON dbo.EXAMPLE_TABLE_HISTORY (SysEndTime ASC, SysStartTime ASC);

CREATE TABLE dbo.EXAMPLE_TABLE (
    ID INT NOT NULL IDENTITY(104729, 1),
    CONSTRAINT PK_EXAMPLE_TABLE
        PRIMARY KEY CLUSTERED (ID),
    -- 'data'
    ColA VARCHAR(255) NULL,
    ColB VARCHAR(255) NULL,
    ColC VARCHAR(255) NULL,
    -- system versioning
    SysStartTime DATETIME2 GENERATED ALWAYS AS ROW START HIDDEN NOT NULL,
    SysEndTime DATETIME2 GENERATED ALWAYS AS ROW END HIDDEN NOT NULL,
    PERIOD FOR SYSTEM_TIME(SysStartTime, SysEndTime)
)
WITH (SYSTEM_VERSIONING = ON (HISTORY_TABLE = dbo.EXAMPLE_TABLE_HISTORY));
GO

Problem

I am running into a strange situation where the results don't appear to be correct unless I add delays into the code. For example, when running the below script I would expect the table to be empty at T0, however it returns data from the first insert.

-- perform simple dml statements
DECLARE @t0 DATETIME2 = SYSUTCDATETIME();
INSERT INTO dbo.EXAMPLE_TABLE (ColA, ColB, ColC) VALUES ('a', NULL, NULL);

DECLARE @t1 DATETIME2 = SYSUTCDATETIME();
UPDATE dbo.EXAMPLE_TABLE SET ColB = 'b' WHERE ColA = 'a';
INSERT INTO dbo.EXAMPLE_TABLE (ColA, ColB, ColC) VALUES ('d', NULL, 'f');

DECLARE @t2 DATETIME2 = SYSUTCDATETIME();
DELETE dbo.EXAMPLE_TABLE WHERE ColA = 'a';

DECLARE @t3 DATETIME2 = SYSUTCDATETIME();

-- inspect tables at specific points in time
SELECT * FROM dbo.EXAMPLE_TABLE FOR SYSTEM_TIME AS OF @t0;
SELECT * FROM dbo.EXAMPLE_TABLE FOR SYSTEM_TIME AS OF @t1;
SELECT * FROM dbo.EXAMPLE_TABLE FOR SYSTEM_TIME AS OF @t2;
SELECT * FROM dbo.EXAMPLE_TABLE FOR SYSTEM_TIME AS OF @t3;
SELECT * FROM dbo.EXAMPLE_TABLE;

'FIX?'

If I add in delays everything seems to work, but I am want to understand if the delays are needed or if they are 'working' accidentaly.

-- perform simple dml statements
DECLARE @t0 DATETIME2 = SYSUTCDATETIME();
WAITFOR DELAY '00:00:00.100';
INSERT INTO dbo.EXAMPLE_TABLE (ColA, ColB, ColC) VALUES ('a', NULL, NULL);

DECLARE @t1 DATETIME2 = SYSUTCDATETIME();
WAITFOR DELAY '00:00:00.100';
UPDATE dbo.EXAMPLE_TABLE SET ColB = 'b' WHERE ColA = 'a';
INSERT INTO dbo.EXAMPLE_TABLE (ColA, ColB, ColC) VALUES ('d', NULL, 'f');

DECLARE @t2 DATETIME2 = SYSUTCDATETIME();
WAITFOR DELAY '00:00:00.100';
DELETE dbo.EXAMPLE_TABLE WHERE ColA = 'a';

DECLARE @t3 DATETIME2 = SYSUTCDATETIME();
WAITFOR DELAY '00:00:00.100';

-- inspect tables at specific points in time
SELECT * FROM dbo.EXAMPLE_TABLE FOR SYSTEM_TIME AS OF @t0;
SELECT * FROM dbo.EXAMPLE_TABLE FOR SYSTEM_TIME AS OF @t1;
SELECT * FROM dbo.EXAMPLE_TABLE FOR SYSTEM_TIME AS OF @t2;
SELECT * FROM dbo.EXAMPLE_TABLE FOR SYSTEM_TIME AS OF @t3;
SELECT * FROM dbo.EXAMPLE_TABLE;

At this point my best guess is SQL Server captures the time at the beginning of the DML statment and there is simply not a long enough delay at the precision of a datetime2 to distinguish between the time captured and the next statement.

Is this assumption correct? Any explanation or documentation would be helpful.

All testing was performed with SQL Server 2017.

Best Answer

You're sort of correct (although not in a good way, as it turns out). From the docs:

The times recorded in the system datetime2 columns are based on the begin time of the transaction itself. For example, all rows inserted within a single transaction will have the same UTC time recorded in the column corresponding to the start of the SYSTEM_TIME period.

Normally though, unless these were explicit transactions, a DATETIME2 variable should have more than enough precision to split the results, but that's not what we're seeing...


Reproducing

This dbfiddle of 2017 matches OP's situation, but if I run locally on my 2017 instance I do not get results for @t0.

I was unable to reproduce locally on an RTM of 2017 (Express) as well as the latest CU 17. I thus began to assume my laptop is either way too fast, or way too slow, to make this discrepancy obvious.

However, after playing around with multiple fiddles I have found the same code is returning different results, which leads me to believe there is undocumented lag or perhaps a bug in the time stamping feature for temporal tables.

Example

dbfiddle enter image description here

enter image description here

enter image description here

Conclusion

It took 50+ executions of the same code to trigger all of these differing results (sorry for spamming the site, Jack) but eventually it became clear that the time stamping for temporal tables cannot be trusted on a sufficiently fast enough system. And not only that, but even when the time stamps matched up the results are still not guaranteed to be the same.

I am assuming this is most apparent on faster servers, since my laptop isn't actually all that great, and the STATISTICS TIME on my local tests were consistently 5-6x higher than the ones dbfiddle was returning.

This is probably worth opening a bug with Microsoft about as it seems to be a pretty problematic behavior.