DMV sys.dm_exec_procedure_stats sometimes returns weird (incorrect?) values ​in successive object snapshots

Question

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.

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.

SET NOCOUNT ON

-- Create a table to hold sys.dm_exec_procedure_stats snapshots
IF OBJECT_ID('tempdb.dbo.#SNAPSHOTS') IS NULL
BEGIN 
    CREATE TABLE #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
    )
END

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

-- Loop indefinitely
WHILE 1 = 1
BEGIN 
    
    -- Get last execution time from the snapshot table
    SELECT @last_execution_time = MAX(last_execution_time), 
            @timestamp = GETDATE()
    FROM #SNAPSHOTS
    
    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
    INSERT INTO #SNAPSHOTS
    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, *
        FROM #SNAPSHOTS
    )
    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

END

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.