I'm working on a small project to monitor activity and execution metrics of user stored procedures. Periodically (every 10 minutes or so), I'm taking snapshots of the sys.dm_exec_procedure_stats DMV, then INNER JOIN successive snapshots on procedure database_id, object_id, plan_handle and plan cached_time columns to calculate execution metrics deltas. The thing which confuses me is that those deltas are sometimes negative, since in some rare cases the exec metrics values ​of the later snapshot are lower than the values ​​of the previous snapshot of the same object. How is it possible?

I'm doing this data collecting / processing thing on several instances and various versions of SQL Server, and, so far, this strange behavior only occurs on SQL Server 2008 R2.

There is an example in the picture below. Highlighted snapshots have lower exec metrics values (total_worker_time, execution_count etc.) compared to the previous snapshot of the same object, which is strange, since both snapshots have the same database_id, object_id, plan_handle and plan caching time.

Please note: those snapshots shown in the picture below were not processed in any way by my script, they are result of the plain old - SELECT "desired columns" FROM sys.dm_exec_procedure_stats.

enter image description here

Just to clarify a bit more what I'm doing, this is the algorithm I'm using for taking snapshots and calculating deltas:

  1. Take a snapshot (S0) from the sys.dm_exec_procedure_stats (SELECT "desired columns" FROM sys.dm_exec_procedure_stats)

  2. Wait some time (let's say - 10 mins);

  3. Take another snapshot (S1) from the sys.dm_exec_procedure_stats (SELECT "desired columns" FROM sys.dm_exec_procedure_stats)

  4. Sort snapshots S0 and S1 by timestamp, do INNER JOIN on database_id, object_id, plan_handle and plan_cached_time columns and calculate execution metrics deltas.

The script which results from this algorithm is quite simple. The thing that bugs me is, when I dump snapshots S0 and S1 on SSMS screen, sometimes (on SQL Server 2008 R2) I get results shown in the picture above where snapshot (S1) have lower execution metrics values compared to snapshot S0, even though they both share the same database_id, object_id, plan_handle and plan_cache_time, and snapshot S1 has higher last_execution_time DATETIME value.

I don't know... Maybe I'm doing something wrong here, but if someone is building a user procedure monitoring script based on aggregated data from sys.dm_exec_procedure_stats DMV, maybe they should be careful, as they might end up with negative deltas on SQL Server 2008 R2.

This is a script I'm using to check for negative/invalid deltas. Please, let me know if it's logic is wrong.
I tested it on SQL Server versions 2008 R2, 2012, 2016, 2017 and 2019, and negative deltas were found only on SQL Server 2008 R2.


-- Create a table to hold sys.dm_exec_procedure_stats snapshots
        timestamp DATETIME2(0), 
        database_id INT, 
        object_id INT, 
        plan_handle VARBINARY(64), 
        plan_cached_time DATETIME, 
        last_execution_time DATETIME, 
        execution_count BIGINT, 
        total_elapsed_time BIGINT, 
        total_worker_time BIGINT, 
        total_logical_reads BIGINT

DECLARE @timestamp DATETIME2(0), @last_execution_time DATETIME, @iteration INT = 0, @negatives INT = 0, @rows INT

-- Loop indefinitely
WHILE 1 = 1
    -- Get last execution time from the snapshot table
    SELECT @last_execution_time = MAX(last_execution_time), 
            @timestamp = GETDATE()
    IF @last_execution_time IS NULL
        SET @last_execution_time = GETDATE() - 30
    -- Take snapshot from sys.dm_exec_procedure_stats DMV of all procs. that were executed after the last snapshot collection time
    SELECT @timestamp, database_id, object_id, plan_handle, cached_time, last_execution_time, execution_count, total_worker_time, total_elapsed_time, total_logical_reads
    FROM sys.dm_exec_procedure_stats
    WHERE last_execution_time > @last_execution_time
    SET @rows = @@ROWCOUNT
    -- Check for negative/invalid deltas
    ;WITH c AS (
        SELECT ROW_NUMBER()OVER(PARTITION BY database_id, object_id, plan_handle, plan_cached_time ORDER BY timestamp) row, *
    SELECT @negatives = COUNT(*)
    FROM c s0 
        INNER JOIN c s1 ON s0.database_id = s1.database_id AND s0.object_id = s1.object_id AND s0.plan_handle = s1.plan_handle AND s0.plan_cached_time = s1.plan_cached_time AND s0.row = s1.row - 1
    WHERE s1.execution_count - s0.execution_count < 0 
        OR s1.total_elapsed_time - s0.total_elapsed_time < 0
        OR s1.total_logical_reads - s0.total_logical_reads < 0
        OR s1.total_worker_time - s0.total_worker_time < 0
    SET @iteration += 1
    RAISERROR(N'Iteration: %d. Rows added: %d. Negative/Invalid deltas: %d', 10, 10, @iteration, @rows, @negatives) WITH NOWAIT

    WAITFOR DELAY '00:01:00' -- Wait a bit before taking another snapshot

  • Recompiles? Aging out of cache? Remember, the DMVs aren't forever. They're cache dependent. It's possibly that 2008R2 dumped stuff out of cache more frequently. For example, in your data set, the snapshot immediately after the first highlighted one is greater than the highlight, but not as great as that preceding. It's growing over time within the cache. Aug 22 at 13:11
  • @GrantFritchey Thank you. But all these snapshots have the same plan caching time (column cached_time), so the plan was in the cache all the time, right? So, how come the later snapshot (highlighted) has lower values than the one that precedes it.
    – Dusan K
    Aug 22 at 14:44
  • You are correct. It is the time the proc was added to the cache. It may be a bug? Not sure. 2008R2 documentation isn't even online any more. Because everything is cache dependent, there's lots of variability in what we see. It's not a flawless system. Stuff in flight isn't reflected. Things that don't go to cache won't be there (RECOMPILE for example). Aug 23 at 11:47

1 Answer 1


Most likely this is due to a subsequent bug fix that wasn't backported as far as SQL Server 2008 R2.

There's nothing I could find directly related to the stated problem in any of the 2005-2014 CU or SP articles I looked at, but that's nothing so unusual since many fixes go undocumented.

If you're really curious about the underlying cause, you could try manually aggregating the data from sys.dm_exec_query_stats (for procedures only) and compare that to the sys.dm_exec_procedure_stats results. Any discrepancy would imply an error in the way the procedure DMV aggregates the data. Assuming your code was error-free, anyway.

Plan caching is a complex area, with many ways to do things wrong. Statement-level recompiles, plan eviction due to memory pressure, uncompiled branches, temporary table caching, simple & forced parameterization are just a some of the complicating factors.

Microsoft are not immune from making coding mistakes, failing to account for edge cases, or falling prey to race conditions.


Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.