Some Statement Start Times!

I thought I had captured statement start times within the DMV sys.dm_exec_sessions. I was absolutely wrong. However, this has sparked a bit of discussion, as you can see in the link to my correction. John Vanda (I couldn’t find a blog by him, but I think this is his LinkedIn profile), suggested possibly joining between the sys.dm_exec_requests and sys.dm_tran_active_transactions through the transaction_id available in the requests DMV. He ran a series of tests that showed it to be promising.

I re-ran my original test, a few long-running statements within a batch; BACKUP, CHECKDB, etc.. This time I captured the transaction information along with the other DMV’s. The results were interesting. Rather than pull together any particular set of data as I was testing, I just collected all three DMV’s once a second, inserting them into tables for later querying. After collecting the data, here’s the query, using my storage tables, that pulled together the DMV data collected once per second during the run of my long running queries:

SELECT dr.command
,dr.start_time
,dt.transaction_begin_time
FROM dbo.dmR AS dr
LEFT JOIN dbo.dmT AS dt
ON dr.transaction_id = dt.transaction_id
WHERE dr.session_id = 59
ORDER BY dt.transaction_begin_time;

The data was interesting. Many of the commands I was running didn’t have transactions associated, BACKUP for example. So there was no transaction_id available for those statements within sys.dm_exec_requests. But, some did and I saw variations in the transaction_begin_time values and the start_time values that delineated the batch. Thanks to John Vanda, a possible breakthrough.

To explore it a bit more, I put together a different test. This time, I wanted mixed CRUD statements, all without explicit transactions, to see how they would break out or if they would break out and, most importantly, if I could see when each statement was started. Here’s the simple test I put together:

TRUNCATE TABLE dbo.Test ;
DECLARE @EndTime DATETIME = DATEADD(ss, 30, GETDATE()) ;
DECLARE @i BIGINT = 0;
INSERT INTO dbo.Test
(col)
VALUES
('Row1')
,('Row2')
,('Row3')
WHILE (@EndTime > GETDATE())
BEGIN
SET @i += 1 ;
SELECT * FROM dbo.Test AS T ;
INSERT INTO dbo.Test
(col)
VALUES ('NRow' + CAST(@i AS VARCHAR)) ;
SELECT * FROM dbo.Test AS T ;
UPDATE dbo.Test
SET col = 'NRow' + CAST((@i - 3) AS VARCHAR)
WHERE col = 'NRow' + CAST((@i - 1) AS VARCHAR) ;
SELECT * FROM dbo.Test AS T ;
END

Obviously, the results are a bit mixed. I was only collecting data once every second. But this time, I’m absolutely seeing changes to the transaction_begin_time that correspond to changes in the statements being called and they are seperate from the batch start_time and it’s not an artifact of the test process like last time.

I don’t think this will work 100% of the time, because statements that lie outside a transaction won’t have a transaction_id value or an associated entry in the transaction DMV, but for those that do, you can get the statement start time.

Well done and thank you to John Vanda.