Czy total_elapsed_time w DMV sys.dm_exec_requests jest całkowicie niedokładny?

13

Korzystam z programu SQL Server 2012 i próbuję zestawić zapytania w celu monitorowania za pomocą DMV. Jednak patrząc na total_elapsed_timepole w sys.dm_exec_requestsDMV, liczby wyglądają na dalekie. Oto przykład:

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

Według moich obliczeń * czas, który upłynął, powinien wynosić około 349 103, a nie 1 499 976. To ponad 4 razy.

* Z różnicy, w milisekundach, między bieżącym czasem a czasem początkowym, tj
SELECT DATEDIFF(MILLISECOND, '2016-04-07T16:08:14.587', '2016-04-07T16:14:03.690');

Oto informacje o serwerze:

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)

Wszelkie pomysły, co może być przyczyną tej rozbieżności?

JoeNahmias
źródło
Prawdopodobnie związany
Aaron Bertrand

Odpowiedzi:

11

Istnieje błąd, który agreguje czas w operacji równoległej. Zostało to naprawione w 2014 roku.

Total_elapsed_time będzie poprawna dla danego zapytania równolegle w partii, aż przechodzi do następnej instrukcji w partii, wówczas total_elapsed_time eksploduje przez DOP.

Przykład

Uruchom to w jednym oknie zapytania:

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'

Uruchom to za sekundę:

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>

Dwie wartości będą prawie identyczne, dopóki SQL Server nie przejdzie do WAITFORDELAYinstrukcji, wtedy powinieneś zobaczyć eksplozję total_elapsed_time (zakładając, że pierwsze zapytanie ma plan równoległy, jak ma to miejsce na moim serwerze).

Pamiętam, jak pracowałem nad tym dla klienta kilka lat temu. Znaleziono błąd w wewnętrznej bazie danych (jestem konsultantem programisty Microsoft Premier), ale nie ma publicznego odniesienia.

Chad Mattox
źródło
7

Wygląda na to, że może to być także błąd / problem z DMV. Istnieje raport o błędach Connect dotyczący tego samego rodzaju niedokładności. Sugerowanym obejściem jest użycie

GETDATE() - sys.dm_exec_requests.start_time

zamiast total_elapsed_time . Problem został rozwiązany w programie SQL Server 2014. Aby zacytować komentarz do elementu Connect przez „Nathan (MSFT)”:

Problem z sys.dm_exec_requests.total_elapsed_time nie jest specyficzny dla RESTOREoperacji; zaobserwowano to również z UPDATE STATISTICS. Ten problem nie zostanie rozwiązany w SQL Server 2008 R2. [...] Problem został rozwiązany w programie SQL Server 2014.

James Rhoat
źródło
2

Sprawdziłem kilka serwerów i na prośbach w tle zaobserwowałem dryf około 14 sekund w ciągu 2 miesięcy.

Jednak poza tym jedyną znaczącą różnicą, którą widzę w innych wnioskach, jest to, gdzie pająk przeszedł w stan SEN. Podejrzewam, że ta wartość nie zwiększa się w tym stanie; ale nie byłem w stanie zmusić zapytania do SLEEPING w celu przetestowania go. (WAITFOR przechodzi w tryb zawieszony zamiast spać).

Mogą być inne przyczyny, ale jeszcze ich nie znalazłem. Możesz wykluczyć to, monitorując zapytanie, aby upewnić się, że nie przejdzie ono w stan SLEEPING.

Cody Konior
źródło