Estou trabalhando em um pequeno projeto para monitorar métricas de atividades e execução de procedimentos armazenados do usuário. Periodicamente (a cada 10 minutos ou mais), estou tirando instantâneos do DMV sys.dm_exec_procedure_stats e, em seguida, INNER JOIN instantâneos sucessivos nas colunas de procedimento database_id, object_id , plan_handle e plan cached_time para calcular deltas de métricas de execução. O que me confunde é que esses deltas às vezes são negativos , já que em alguns casos raros os valores das métricas exec do snapshot posterior são inferiores aos valores do snapshot anterior do mesmo objeto. Como isso é possível?
Estou fazendo essa coisa de coleta/processamento de dados em diversas instâncias e diversas versões do SQL Server e, até o momento, esse comportamento estranho ocorre apenas no SQL Server 2008 R2.
Há um exemplo na imagem abaixo. Os instantâneos destacados têm valores de métricas exec mais baixos (total_worker_time, execução_count etc.) em comparação com o instantâneo anterior do mesmo objeto, o que é estranho, uma vez que ambos os instantâneos têm o mesmo database_id, object_id, plan_handle e tempo de cache do plano.
Observação: os instantâneos mostrados na imagem abaixo não foram processados de forma alguma pelo meu script, eles são o resultado do antigo - SELECT "colunas desejadas" FROM sys.dm_exec_procedure_stats .
Só para esclarecer um pouco mais o que estou fazendo, este é o algoritmo que estou usando para tirar snapshots e calcular deltas:
Tire um instantâneo (S0) de sys.dm_exec_procedure_stats ( SELECT "colunas desejadas" FROM sys.dm_exec_procedure_stats )
Espere um pouco (digamos - 10 minutos);
Tire outro instantâneo (S1) de sys.dm_exec_procedure_stats ( SELECT "colunas desejadas" FROM sys.dm_exec_procedure_stats )
Classifique os snapshots S0 e S1 por carimbo de data/hora, faça INNER JOIN nas colunas database_id, object_id, plan_handle e plan_cached_time e calcule os deltas das métricas de execução.
O script que resulta deste algoritmo é bastante simples. O que me incomoda é que, quando despejo os instantâneos S0 e S1 na tela do SSMS, às vezes (no SQL Server 2008 R2) obtenho resultados mostrados na imagem acima, onde o instantâneo (S1) tem valores de métricas de execução mais baixos em comparação com o instantâneo S0, mesmo embora ambos compartilhem o mesmo database_id, object_id, plan_handle e plan_cache_time, e o snapshot S1 tenha um valor DATETIME last_execution_time mais alto .
Não sei... Talvez eu esteja fazendo algo errado aqui, mas se alguém estiver construindo um script de monitoramento de procedimento do usuário com base em dados agregados do DMV sys.dm_exec_procedure_stats, talvez deva ter cuidado, pois pode acabar com negativo deltas no SQL Server 2008 R2.
Este é um script que estou usando para verificar deltas negativos/inválidos. Por favor, deixe-me saber se a lógica está errada.
Testei nas versões do SQL Server 2008 R2, 2012, 2016, 2017 e 2019, e deltas negativos foram encontrados apenas no 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
Provavelmente, isso se deve a uma correção de bug subsequente que não foi portada até o SQL Server 2008 R2.
Não há nada que eu possa encontrar diretamente relacionado ao problema declarado em qualquer um dos artigos CU ou SP de 2005-2014 que li, mas isso não é nada incomum, já que muitas correções não são documentadas.
Se você estiver realmente curioso sobre a causa subjacente, tente agregar manualmente os dados
sys.dm_exec_query_stats
(apenas para procedimentos) e compará-los com ossys.dm_exec_procedure_stats
resultados. Qualquer discrepância implicaria em erro na forma como o procedimento do DMV agrega os dados. Supondo que seu código esteja livre de erros, de qualquer maneira.O cache de planejamento é uma área complexa, com muitas maneiras de fazer coisas erradas. Recompilações em nível de instrução, remoção de planos devido à pressão de memória, ramificações não compiladas, cache temporário de tabelas, parametrização simples e forçada são apenas alguns dos fatores complicadores.
A Microsoft não está imune a cometer erros de codificação, deixar de levar em conta casos extremos ou ser vítima de condições de corrida.