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.

3 thoughts on “Some Statement Start Times!

  • John Vanda

    Thanks for the kudos. I’m happy to contribute to such a well respected blog. Yes, that is my LinkedIn profile. I’m working up the courage to start my own blog. I do have a twitter called OrdinaryDBA.

  • John Vanda

    That’s pretty awesome. Thank you very much 🙂 I tried diligently to watch, but it wasn’t very os x friendly for the audio. I tried watching from an RDC to a Windows server, but audio is disabled over RDC for Live Meeting. Hopefully I can get the recording somehow.

Please let me know what you think about this article or any questions:

This site uses Akismet to reduce spam. Learn how your comment data is processed.