¿Total_elapsed_time en DMV sys.dm_exec_requests es completamente inexacto?

13

Estoy ejecutando SQL Server 2012 y estoy tratando de reunir algunas consultas para monitorear usando los DMV. Sin embargo, al mirar el total_elapsed_timecampo en el sys.dm_exec_requestsDMV, los números se ven muy lejos. Aquí hay un ejemplo:

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

Según mis cálculos *, el tiempo transcurrido debería ser de alrededor de 349,103, no de 1,419,976. Eso es más de un factor de 4.

* De la diferencia, en milisegundos, entre la hora actual y la hora de inicio, es decir
SELECT DATEDIFF(MILLISECOND, '2016-04-07T16:08:14.587', '2016-04-07T16:14:03.690');

Aquí está la información del 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)

¿Alguna idea de lo que podría estar causando esta discrepancia?

JoeNahmias
fuente
Posiblemente relacionado
Aaron Bertrand

Respuestas:

11

Hay un error que agrega el tiempo en una operación paralela. Esto se solucionó en 2014.

El total_elapsed_time será correcta para una consulta en paralelo particular, en un lote hasta que se mueva a la siguiente instrucción del lote, entonces la total_elapsed_time explotará por la DOP.

Ejemplo

Ejecute esto en una ventana 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'

Ejecute esto en un 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>

Los dos valores serán casi idénticos hasta que SQL Server se mueva a la WAITFORDELAYinstrucción, entonces debería ver la explosión total_elapsed_time (suponiendo que la primera consulta tenga un plan paralelo como lo hace en mi servidor).

Recuerdo haber trabajado en esto para un cliente hace unos años. Encontré el error en la base de datos interna (soy un consultor de desarrolladores Premier de Microsoft), pero no hay referencia pública.

Chad Mattox
fuente
7

Parece que también podría ser un error / problema con el DMV. Hay un informe de error Conectar aquí de este mismo tipo de imprecisión. La solución sugerida es usar

GETDATE() - sys.dm_exec_requests.start_time

en lugar de total_elapsed_time . El problema se resuelve en SQL Server 2014. Para citar el comentario sobre el elemento Connect de "Nathan (MSFT)":

El problema con sys.dm_exec_requests.total_elapsed_time no es específico de las RESTOREoperaciones; También se ha observado con UPDATE STATISTICS. Este problema no se resolverá en SQL Server 2008 R2. [...] El problema se resuelve en SQL Server 2014.

James Rhoat
fuente
2

Revisé un par de servidores y en las solicitudes en segundo plano observé una deriva de aproximadamente 14 segundos durante 2 meses.

Sin embargo, aparte de eso, la única diferencia significativa que puedo ver en otras solicitudes es cuando el spid ha entrado en estado de DORMIR. Sospecho que este valor no aumenta mientras está en ese estado; pero no he podido forzar una consulta en SLEEPING para probarla. (WAITFOR va a suspender en lugar de dormir).

Puede haber otras causas, pero aún no he encontrado ninguna. Puede descartarlo al monitorear su consulta para asegurarse de que no pase al estado de DORMIR.

Cody Konior
fuente