Friday, 15 June 2012

sys.dm_exec_requests: total_elapsed_time column may return inconsistent data

Developing useful scripts for administration purposes, I have found a bug with respect to data recollected by 'sys.dm_exec_requests' dynamic management view on SQL Server 2008 R2 SP2 while I was analysing the total elapsed time for a particular SQL query. Let me expand on what I am saying. I did detect an error in the 17th second of the execution with 'session_id' equal to 63 (see it in the picture). Following the sequence of each result in the execution of queries, I need to draw your attention to the second query and its second column where the total elapsed time according to 'sys.dm_exec_requests' should be 17 and not 938 seconds since the previous one was 16. Now, checking the value of the third column (calculated by subtracting the 'start_time' value from GETDATE function), you will verify that this time is accurate whereas the second one is false. The value for the second and third columns should be the same but they are different.

To sum up, for this particular and real case, the column 'total_elapsed_time' returns inconsistent information about elapsed execution time of a process when it exceeds 16 seconds. Therefore, I suggest working with caution and not trusting in DMVs so much. That is all for now, let me know any remark you may have. Thanks for reading.