Sys.dm_exec_requests and cpu_time

You'd have to be polling sys.dm_exec_requests rather frequently, or using trace / extended events to target queries that ended with abort. With the disclaimer that I work for SQL Sentry, Performance Advisor - among many other things - tracks all aborted queries for you, as long as they exceed the Top SQL threshold (5 seconds by default, but that is configurable). It's possible other monitoring tools might do something similar.

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.