Total_elapsed_time no DMV sys.dm_exec_requests é completamente impreciso?

13

Estou executando o SQL Server 2012 e estou tentando reunir algumas consultas para monitorar usando as DMVs. No entanto, ao olhar para o total_elapsed_timecampo na sys.dm_exec_requestsDMV, os números parecem muito diferentes. Aqui está um exemplo:

SELECT
  session_id, RunTime = CURRENT_TIMESTAMP,
  start_time, total_elapsed_time
FROM sys.dm_exec_requests
WHERE session_id = 284;

session_id  RunTime                 start_time              total_elapsed_time
284         2016-04-07 16:14:03.690 2016-04-07 16:08:14.587 1419976

Pelos meus cálculos *, o tempo decorrido deve ficar em torno de 349.103 - não 1.419.976. Isso é mais do que um fator de 4.

* Da diferença, em milissegundos, entre o horário atual e o start_time, ou seja,
SELECT DATEDIFF(MILLISECOND, '2016-04-07T16:08:14.587', '2016-04-07T16:14:03.690');

Aqui estão as informações do servidor:

SELECT @@VERSION;

Microsoft SQL Server 2012 - 11.0.5592.0 (X64) 
    Apr 17 2015 15:18:46 
    Copyright (c) Microsoft Corporation
    Enterprise Edition: Core-based Licensing (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)

Alguma idéia do que poderia estar causando essa discrepância?

JoeNahmias
fonte
Possivelmente relacionado
Aaron Bertrand

Respostas:

11

Há um erro que agrega o tempo em uma operação paralela. Isso foi corrigido em 2014.

O total_elapsed_time estará correto para uma consulta paralela específica em um lote até passar para a próxima instrução do lote, e o total_elapsed_time explodirá pelo DOP.

Exemplo

Execute isso em uma janela de consulta:

USE AdventureWorks2012
GO
SELECT *
FROM Sales.SalesOrderDetail sod
JOIN Production.Product p ON sod.ProductID = p.ProductID
ORDER BY Style 

waitfor delay '00:00:15'

Execute isso em um segundo:

select 
    DATEDIFF(ms, start_time, getdate()) ActualElapsedTime,
    total_elapsed_time from sys.dm_exec_requests
where session_id = <your session_id for the above batch>

Os dois valores ficarão quase idênticos até o SQL Server passar para a WAITFORDELAYinstrução, então você verá o total_elapsed_time explodir (supondo que a primeira consulta tenha um plano paralelo, como no meu servidor).

Lembro-me de trabalhar nisso para um cliente há alguns anos. Encontrei o bug no banco de dados interno (sou um Microsoft Premier Developer Consultant), mas nenhuma referência pública.

Chad Mattox
fonte
7

Parece que também pode ser um bug / problema com o DMV. Há um relatório de bug do Connect aqui com esse mesmo tipo de imprecisão. A solução alternativa sugerida é usar

GETDATE() - sys.dm_exec_requests.start_time

em vez de total_elapsed_time . O problema foi resolvido no SQL Server 2014. Para citar o comentário no item do Connect por "Nathan (MSFT)":

O problema com sys.dm_exec_requests.total_elapsed_time não é específico para RESTOREoperações; também foi observado com UPDATE STATISTICStambém. Este problema não será resolvido no SQL Server 2008 R2. [...] o problema foi resolvido no SQL Server 2014.

James Rhoat
fonte
2

Eu verifiquei alguns servidores e, em segundo plano, os pedidos observaram um desvio de cerca de 14s em 2 meses.

No entanto, além disso, a única diferença significativa que posso ver em outras solicitações é onde o spid entrou em um estado de DORMIR. Suspeito que esse valor não seja incrementado enquanto estiver nesse estado; mas não consegui forçar uma consulta no SLEEPING para testá-la. (WAITFOR vai para suspenso em vez de dormir).

Pode haver outras causas, mas ainda não encontrei nenhuma. Você pode excluir essa questão monitorando sua consulta para garantir que ela não entre no estado DORMIR.

Cody Konior
fonte