Apakah total_elapsed_time di DMV sys.dm_exec_requests sepenuhnya tidak akurat?

13

Saya menjalankan SQL Server 2012 dan saya mencoba untuk mengumpulkan beberapa pertanyaan bersama untuk pemantauan menggunakan DMV. Namun, ketika melihat total_elapsed_timebidang di sys.dm_exec_requestsDMV, angkanya terlihat jauh. Ini sebuah contoh:

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

Menurut kalkulasi saya *, waktu yang berlalu seharusnya sekitar 349.103 - bukan 1.419.976. Itu lebih dari faktor 4.

* Dari perbedaan, dalam milidetik, antara waktu saat ini dan start_time yaitu
SELECT DATEDIFF(MILLISECOND, '2016-04-07T16:08:14.587', '2016-04-07T16:14:03.690');

Inilah info server:

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)

Adakah ide yang dapat menyebabkan perbedaan ini?

JoeNahmias
sumber
Kemungkinan terkait
Aaron Bertrand

Jawaban:

11

Ada bug yang mengagregasi waktu dalam operasi paralel. Ini diperbaiki pada tahun 2014.

The total_elapsed_time akan benar untuk query paralel tertentu dalam batch sampai pindah ke pernyataan berikutnya dalam batch, maka total_elapsed_time akan meledak oleh DOP.

Contoh

Jalankan ini dalam satu jendela permintaan:

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'

Jalankan ini sebentar lagi:

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>

Dua nilai akan mendekati identik sampai SQL Server bergerak ke WAITFORDELAYpernyataan, maka Anda akan melihat meledak total_elapsed_time (dengan asumsi permintaan pertama memiliki rencana paralel seperti halnya di server saya).

Saya ingat mengerjakan ini untuk pelanggan beberapa tahun yang lalu. Menemukan bug di basis data internal (saya seorang Konsultan Pengembang Microsoft Premier), tetapi tidak ada referensi publik.

Chad Mattox
sumber
7

Sepertinya itu juga bisa menjadi bug / masalah dengan DMV. Ada laporan bug Connect di sini tentang ketidakakuratan yang sama. Solusi yang disarankan adalah menggunakan

GETDATE() - sys.dm_exec_requests.start_time

bukannya total_elapsed_time . Masalah ini diatasi dalam SQL Server 2014. Mengutip komentar pada item Connect oleh "Nathan (MSFT)":

Masalah dengan sys.dm_exec_requests.total_elapsed_time tidak spesifik untuk RESTOREoperasi; itu juga telah diamati dengan UPDATE STATISTICSbaik. Masalah ini tidak akan diselesaikan dalam SQL Server 2008 R2. [...] Masalahnya diselesaikan di SQL Server 2014.

James Rhoat
sumber
2

Saya telah memeriksa beberapa server dan pada permintaan latar belakang mengamati pergeseran sekitar 14-an selama 2 bulan.

Namun selain itu, satu-satunya perbedaan signifikan yang dapat saya lihat pada permintaan lain adalah di mana spid telah berubah menjadi keadaan TIDUR. Saya menduga bahwa nilai ini tidak bertambah saat dalam keadaan itu; tapi saya belum bisa memaksa kueri ke TIDUR untuk mengujinya. (WAITFOR pergi ke ditangguhkan daripada tidur).

Mungkin ada penyebab lain tetapi saya belum menemukannya. Anda bisa mengesampingkan yang satu ini dengan memantau permintaan Anda untuk memastikannya tidak masuk ke status TIDUR.

Cody Konior
sumber