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:
Take a snapshot (S0) from the sys.dm_exec_procedure_stats (SELECT "desired columns" FROM sys.dm_exec_procedure_stats)
Wait some time (let's say - 10 mins);
Take another snapshot (S1) from the sys.dm_exec_procedure_stats (SELECT "desired columns" FROM sys.dm_exec_procedure_stats)
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