When did this statement start?

UPDATE: This post is incorrect. Adam nailed it in the comments. I explain my mistake here.

A question came up over at SQL Server Central where someone was wondering if it was possible to know when a given statement within a batch started. Immediately I thought, oh yeah, that’s easy, use the sys.dm_exec_requests dynamic management view (DMV). Done.

Wrong. The original poster pointed out that I had assumed that the values present in the DMV represented statement level values, but they show the batch. While the DMV shows a start_time, that time is the start of the current batch, not the statement within the batch. Now the question was, where else might I get this data? I next tried sys.dm_exec_sessions because it has the last_request_start_time value. Sure enough this worked.

Don’t believe me? This time I tested it. First, I set up a batch that ran a few longish queries:

BACKUP DATABASE AdventureWorks
TO DISK = 'c:\bu\ad.bak'
WITH INIT;
DBCC CHECKALLOC(AdventureWorks);
DBCC CHECKDB(AdventureWorks);
DBCC CHECKCATALOG(AdventureWorks);
BACKUP DATABASE AdventureWorks
TO DISK = 'c:\bu\ad.bak'
WITH INIT; 

Then I wrote a little loop that would insert data from both DMV’s, once every second for a minute:

SET NOCOUNT ON;
TRUNCATE TABLE dbo.dmR;
TRUNCATE TABLE dbo.dmS;
DECLARE @CheckTime DATETIME = DATEADD(ss,60,GETDATE())
 ,@CurrTime DATETIME = GETDATE();
WHILE @CurrTime < @CheckTime
BEGIN
INSERT INTO ... SELECT ... FROM sys.dm_exec_sessions
INSERT INTO ... SELECT ... FROM sys.dm_exec_requests
WAITFOR DELAY '00:00:01';
SET @CurrTime = GETDATE();
END

Then it was a question of hitting the go button. The results are pretty clear. If you look at sys.dm_exec_requests data, you’ll see the start_time doesn’t change, but, the work being performed, visible in the command and plan_handle columns changes. You can also see the statement_start_offset and statement_end_offset changing. These values will allow you to pull data in combination with the sys.dm_exec_sql_text() dynamic management function.

 start_time             command         statement_start_offset statement_end_offset plan_handle
2009-07-28 10:42:09.447 BACKUP DATABASE 0                      138                  0x060001007D931719B8C0BF0D000000000000000000000000
2009-07-28 10:42:09.447 DBCC            140                    206                  0x060001007D931719B8C0BF0D000000000000000000000000
2009-07-28 10:42:09.447 DBCC            140                    206                  0x06000F00AF16F10FB8C04D0D000000000000000000000000
2009-07-28 10:42:09.447 DBCC            208                    268                  0x060001007D931719B8C0BF0D000000000000000000000000

But, as you can see, the start_time stays the same. Looking at the last_request_start_time and last_request_end_time in the sys.dm_exec_sessions DMV, you can see these values changing in conjunction with the changing values in sys.dm_exec_requests.

last_request_start_time last_request_end_time
2009-07-28 10:35:21.500 2009-07-28 10:35:51.170
2009-07-28 10:42:09.447 2009-07-28 10:35:51.170 

I’ll leave at as an excercise for the reader (or for another post for myself) to put together the DMV’s and DMF’s that would allow you to combine this data and show exactly which statement was being executed at which moment. The point, it is possible to determine exactly which statement is currently being executed within a batch process, and when that statement started.

7 thoughts on “When did this statement start?

  • Grant,

    I don’t think this is correct, or at least not 100% of the time. The following certainly indicates otherwise (it shows that the last_request_start_time is always equal to the request.start_time, for the entire duration of the batch):


    waitfor delay ’00:00:10′

    select start_time, last_request_start_time
    from sys.dm_exec_requests r
    join sys.dm_exec_sessions s on r.session_id = s.session_id
    where s.session_id = @@spid

    waitfor delay ’00:00:10′

    select start_time, last_request_start_time
    from sys.dm_exec_requests r
    join sys.dm_exec_sessions s on r.session_id = s.session_id
    where s.session_id = @@spid

  • Also, is it a cut and paste error, or did you really get a start_time change without a corresponding end_time change? See the second row below, copied from your post:

    last_request_start_time last_request_end_time
    2009-07-28 10:35:21.500 2009-07-28 10:35:51.170
    2009-07-28 10:42:09.447 2009-07-28 10:35:51.170

  • One more comment, I tried the code below, and it once again showed the same results for both counters. Sorry to keep beating on this, but I’m especially interested in this topic as my Who is Active? script ( http://sqlblog.com/files/folders/beta/entry15064.aspx ) uses these values all over the place and if you’re correct then my script is full of bugs


    select start_time, last_request_start_time
    from sys.dm_exec_requests r
    join sys.dm_exec_sessions s on r.session_id = s.session_id
    where s.session_id = @@spid

    BACKUP DATABASE AdventureWorks
    TO DISK = ‘c:\temp\ad.bak’
    WITH INIT;
    DBCC CHECKALLOC(AdventureWorks);
    DBCC CHECKDB(AdventureWorks);
    DBCC CHECKCATALOG(AdventureWorks);
    BACKUP DATABASE AdventureWorks
    TO DISK = ‘c:\temp\ad.bak’
    WITH INIT;

    select start_time, last_request_start_time
    from sys.dm_exec_requests r
    join sys.dm_exec_sessions s on r.session_id = s.session_id
    where s.session_id = @@spid

  • scarydba

    No, if I got it wrong, I want, need, to know.

    You’re right, the first test shows this to be incorrect, at least in that situation… Weird.

    No, the last request end time showed the same values in some instances.

    Your last test shows the same… I’m resetting my test & trying it again. Something is going on here. I’ll post again in a bit.

  • Oh yeah, I use extended events all the time. But if you don’t have them immediately set up to pull out this information ahead of time, you can fall back on the DMO queries to pull this type of information out. Thanks for the link to Jonathan. He’s probably the greatest when it comes to exevents out there.

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.