Sql-server – sys.dm_exec_requests – start_time

dmvsql server

I have the following query that tells me the status of queries in a database I'm responsible for (although I am not a DBA).

SELECT 
     T3.FullStatement as FullSQLStatement
    ,T3.ExecutingStatement
    ,req.session_id as SessionId
    ,T2.login_name as LoginName
    ,command as SQLCommand
    ,start_time as StartTime
    ,DateDiff(MINUTE,start_time,GetDate()) as ElapsedTimeMinutes
    ,req.status as QueryStatus
    ,req.wait_type as WaitType
    ,req.wait_time as WaitTimeMs
    ,blocking_session_id as BlockingSessionId
    ,req.row_count as [RowCount]
    ,req.cpu_time as CpuTimeMs
    ,req.total_elapsed_time as TotalElapsedTimeMs
    ,SubString(sqltext.TEXT,req.statement_start_offset,req.statement_end_offset-req.statement_start_offset)
FROM sys.dm_exec_requests req
    Inner Join sys.dm_exec_sessions T2 ON T2.session_id = req.session_id
    Cross Apply dbo.GetExecutingSQLStatement (req.session_id) T3
    Cross Apply sys.dm_exec_sql_text(sql_handle) AS sqltext
where req.database_id = 5
Order By 6 Desc

It generates output that looks, partly, as follows:

enter image description here
Even though it doesn't show very well in the example I've included, the start_time is the start time of the full statement and not the executing portion of the statement. Is there somewhere I can get the start time of the executing portion along with the start time of the full statement. This is important to me because, obviously, a full statement could have many individual queries.

Best Answer

At the moment this does not seem like a possible value to get, which is unfortunate as this does seem like a handy value to have.

Ok, I did find it (mostly). There is a last_execution_time field in the sys.dm_exec_query_stats DMV, though that DMV comes with the following warning:

An initial query of sys.dm_exec_query_stats might produce inaccurate results if there is a workload currently executing on the server. More accurate results may be determined by rerunning the query.

Also, I am not sure how the value of last_execution_time is affected by multiple concurrent executions of the exact same SQL across multiple sessions since sys.dm_exec_query_stats is per query batch, not per session.

Below is what I have so far. There is maybe one thing I kinda want to clean up, but this should already account for the first query in a batch which will not have a corresponding entry in sys.dm_exec_query_stats since that gets populated (ideally, but not always in a timely manner) after the current statement / query completes. And it seems to work for single-query batches, so try it out.

SELECT req.session_id AS [SessionID],
       req.start_time AS [BatchStartTime],
       req.total_elapsed_time as [BatchMilliseconds], --[TotalElapsedTimeMs],
       CASE WHEN stat.last_execution_time IS NOT NULL THEN
                DATEADD(MILLISECOND,
                        (stat.last_elapsed_time / 1000.0),
                        stat.last_execution_time)
            ELSE req.start_time END AS [StatementStartTime],
       DATEDIFF(MILLISECOND,
                CASE WHEN stat.last_execution_time IS NOT NULL THEN
             DATEADD(MILLISECOND, (stat.last_elapsed_time / 1000.0),
                stat.last_execution_time)
                  ELSE req.start_time END, GETDATE()) AS [StatementMilliseconds],
       T2.login_name AS [LoginName],
       req.command AS [SQLCommand],
       req.[status] AS [QueryStatus],
       req.wait_type AS [WaitType],
       req.wait_time AS [WaitTimeMs],
       blocking_session_id AS [BlockingSessionId],
       req.row_count AS [RowCount],
       req.cpu_time AS [CpuTimeMs],
       sqltext.[text] AS [QueryBatch],
       SUBSTRING(sqltext.[text],
                 req.statement_start_offset / 2,
                 CASE req.statement_end_offset
                      WHEN -1 THEN DATALENGTH(sqltext.[text])
                      ELSE (req.statement_end_offset - req.statement_start_offset) / 2
                 END) AS [CurrentQuery]
FROM sys.dm_exec_requests req
INNER JOIN sys.dm_exec_sessions T2
        ON T2.session_id = req.session_id
LEFT JOIN sys.dm_exec_query_stats stat
        ON stat.[sql_handle] = req.[sql_handle]
       AND stat.statement_end_offset = (req.statement_start_offset - 2)
CROSS APPLY sys.dm_exec_sql_text(req.[sql_handle]) sqltext
-- WHERE req.session_id = 56
ORDER BY req.start_time;

I have been testing with your query (slightly modified) and the following SQL running in another tab / session (the TOP(1), TOP(2), etc, and 10.1, 10.2, etc on the WAITFOR times are to make it easily visible which statement is being processed when looking at the current statement field):

SELECT GETDATE() AS [StartTime];
GO
SELECT TOP(1) [name] FROM sys.objects;
WAITFOR DELAY '00:00:10.1';

SELECT TOP(2) [name] FROM sys.objects;
WAITFOR DELAY '00:00:10.2';

SELECT TOP(3) [name] FROM sys.objects;
WAITFOR DELAY '00:00:10.3';

SELECT TOP(4) [name] FROM sys.objects;
WAITFOR DELAY '00:00:10.4';

Then just run your query several times and it is pretty clear that dm_exec_requests.start_time and dm_exec_sessions.last_request_start_time are:

  • the same value, and
  • do not change at all during the execution of that batch.

I did try getting the execution plan via CROSS APPLY sys.dm_exec_text_query_plan(req.plan_handle, req.statement_end_offset, req.statement_end_offset) tplan, but that was NULL so not very helpful.

In order to test with your query, I had to remove the first two columns and the reference to the dbo.GetExecutingSQLStatement function. This is probably something you could also get rid of since you have that logic in this query already via CROSS APPLY sys.dm_exec_sql_text(req.[sql_handle]). You just need to make the following three changes:

  • T3.FullStatement (Select field # 1) becomes sqltext.[text]

  • T3.ExecutingStatement (Select field # 2) becomes SUBSTRING(sqltext.[text], req.statement_start_offset / 2, CASE req.statement_end_offset WHEN -1 THEN LEN(sqltext.[text]) ELSE (req.statement_end_offset - req.statement_start_offset) / 2 END)

  • Remove the SUBSTRING (your current last field). If you look closely at the SUBSTRING I am suggesting directly above, it is essentially what you had at the end there, expect it corrects for two mistakes:

    • Your SUBSTRING did not account for when there was only 1 query in the batch, in which case statement_end_offset is -1 and your substring gets an error
    • Your SUBSTRING did not account for the translation of double-byte byte count into character count.

But I digress.

Related Question