When did this statement start?

Home / SQL Server 2005 / 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:

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

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.

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.

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 Comments

  • 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.

OK, fine, but what do you think?