SQL Clone
SQLServerCentral is supported by Redgate
Log in  ::  Register  ::  Not logged in

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
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:

WHILE (@EndTime > GETDATE())
SET @i += 1 ;
SELECT * FROM dbo.Test AS T ;
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 ;

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.

The Scary DBA

I have twenty+ years experience in IT. That time was spent in technical support, development and database administration. I work forRed Gate Software as a Product Evangelist. I write articles for publication at SQL Server Central, Simple-Talk, PASS Book Reviews and SQL Server Standard. I have published two books, ”Understanding SQL Server Execution Plans” and “SQL Server 2008 Query Performance Tuning Distilled.” I’m one of the founding officers of the Southern New England SQL Server Users Group and its current president. I also work on part-time, short-term, off-site consulting contracts. In 2009 and 2010 I was awarded as a Microsoft SQL Server MVP. In the past I’ve been called rough, intimidating and scary. To which I usually reply, “Good.” You can contact me through grant -at- scarydba dot kom (unobfuscate as necessary).


Posted by Anonymous on 12 August 2009

Pingback from  Dew Drop – August 12, 2009 | Alvin Ashcraft's Morning Dew

Posted by Steve Jones on 28 August 2009

Excellent job!

Leave a Comment

Please register or log in to leave a comment.