Sql-Server

針對加入 sys.databases 的查詢統計資訊和執行計劃對 DMV 執行查詢

  • May 19, 2016

我最初在 Twitter #sqlhelp 中將此作為一個不同的問題發布,但想在這里以不同的方式發布。

我正在嘗試使用 DMV dm_exec_query_statsdm_exec_cached_plansdm_exec_sql_text以及最初的sys.databases創建一個跟踪各種統計數據(例如讀取、寫入、CPU、執行計數等)性能最差的語句的作業。

發生的情況是,這個查詢有時會(而不是所有時間)在繁忙的伺服器上執行超過 8 分鐘,但是一旦我刪除了對sys.databases的連接,只需要 9 秒。這段時間的大部分時間是 CPU 時間,幾乎沒有等待,沒有阻塞,沒有掃描,只有 13406 次邏輯讀取和 1562 次 lob 讀取。

所以我想知道,為什麼加入 sys.databases 會對性能造成巨大影響?為什麼不一致?

發生的情況是,當我執行以下測試查詢時,有時無緣無故需要 8 分鐘以上,而其他時間則在 11 秒內完成。

SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
SET NOCOUNT ON;
DECLARE @snapshot_timeoffset AS datetimeoffset(3) = CAST(SYSDATETIMEOFFSET() AS datetimeoffset(3));

SELECT
   @snapshot_timeoffset AS [snapshot_timeoffset]
   ,db.name AS [database_name]  
   ,OBJECT_SCHEMA_NAME(st.objectid, st.dbid) [schema_name] 
   ,OBJECT_NAME(st.objectid, st.dbid) [object_name]   
   ,cp.objtype
   ,cp.usecounts
   ,cp.refcounts
   -- find the offset of the actual statement being executed
   ,SUBSTRING(st.text, 
           CASE
               WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
               ELSE qs.statement_start_offset/2 + 1
           END, 
           CASE 
               WHEN qs.statement_end_offset = 0 OR qs.statement_end_offset = -1 OR qs.statement_end_offset IS NULL THEN LEN(st.text)  
               ELSE qs.statement_end_offset/2 
           END - 
           CASE
               WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
               ELSE qs.statement_start_offset/2
           END + 1 
       ) AS [statement]  
   ,qs.execution_count
   ,qs.total_logical_reads
   ,qs.last_logical_reads
   ,qs.min_logical_reads
   ,qs.max_logical_reads
   ,qs.total_logical_writes
   ,qs.last_logical_writes
   ,qs.min_logical_writes
   ,qs.max_logical_writes
   ,qs.total_physical_reads
   ,qs.last_physical_reads
   ,qs.min_physical_reads
   ,qs.max_physical_reads
   ,qs.total_worker_time
   ,qs.last_worker_time
   ,qs.min_worker_time
   ,qs.max_worker_time
   ,qs.total_clr_time
   ,qs.last_clr_time
   ,qs.min_clr_time
   ,qs.max_clr_time
   ,qs.total_elapsed_time
   ,qs.last_elapsed_time
   ,qs.min_elapsed_time
   ,qs.max_elapsed_time
   ,qs.total_rows
   ,qs.last_rows
   ,qs.min_rows
   ,qs.max_rows
   ,qs.last_execution_time
   ,qs.creation_time
   ,qs.sql_handle
   ,qs.plan_handle
   ,qs.statement_start_offset
   ,qs.statement_end_offset
INTO #QueryStats
FROM master.sys.dm_exec_query_stats qs   
INNER JOIN  master.sys.dm_exec_cached_plans cp 
ON qs.plan_handle = cp.plan_handle 
CROSS APPLY  master.sys.dm_exec_sql_text(qs.plan_handle) st 
INNER JOIN  master.sys.databases db
ON st.dbid = db.database_id;

糟糕的計劃

一次偶然的機會,我決定刪除sys.databases的內部連接,並用函式替換數據庫名稱的查找DB_NAME(),現在它在 9 秒內始終如一地執行:

SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
SET NOCOUNT ON;
DECLARE @snapshot_timeoffset AS datetimeoffset(3) = CAST(SYSDATETIMEOFFSET() AS datetimeoffset(3));

SELECT
   @snapshot_timeoffset AS [snapshot_timeoffset]
   ,DB_NAME(st.dbid) AS [database_name]  
   ,OBJECT_SCHEMA_NAME(st.objectid, st.dbid) [schema_name] 
   ,OBJECT_NAME(st.objectid, st.dbid) [object_name]   
   ,cp.objtype
   ,cp.usecounts
   ,cp.refcounts
   -- find the offset of the actual statement being executed
   ,SUBSTRING(st.text, 
           CASE
               WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
               ELSE qs.statement_start_offset/2 + 1
           END, 
           CASE 
               WHEN qs.statement_end_offset = 0 OR qs.statement_end_offset = -1 OR qs.statement_end_offset IS NULL THEN LEN(st.text)  
               ELSE qs.statement_end_offset/2 
           END - 
           CASE
               WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
               ELSE qs.statement_start_offset/2
           END + 1 
       ) AS [statement]  
   ,qs.execution_count
   ,qs.total_logical_reads
   ,qs.last_logical_reads
   ,qs.min_logical_reads
   ,qs.max_logical_reads
   ,qs.total_logical_writes
   ,qs.last_logical_writes
   ,qs.min_logical_writes
   ,qs.max_logical_writes
   ,qs.total_physical_reads
   ,qs.last_physical_reads
   ,qs.min_physical_reads
   ,qs.max_physical_reads
   ,qs.total_worker_time
   ,qs.last_worker_time
   ,qs.min_worker_time
   ,qs.max_worker_time
   ,qs.total_clr_time
   ,qs.last_clr_time
   ,qs.min_clr_time
   ,qs.max_clr_time
   ,qs.total_elapsed_time
   ,qs.last_elapsed_time
   ,qs.min_elapsed_time
   ,qs.max_elapsed_time
   ,qs.total_rows
   ,qs.last_rows
   ,qs.min_rows
   ,qs.max_rows
   ,qs.last_execution_time
   ,qs.creation_time
   ,qs.sql_handle
   ,qs.plan_handle
   ,qs.statement_start_offset
   ,qs.statement_end_offset
INTO #QueryStats
FROM master.sys.dm_exec_query_stats qs   
INNER JOIN  master.sys.dm_exec_cached_plans cp 
ON qs.plan_handle = cp.plan_handle 
CROSS APPLY  master.sys.dm_exec_sql_text(qs.plan_handle) st;

在此處輸入圖像描述

注意:表值函式[SYSDMEXECCACHEDPLANS]在良好計劃中具有估計 CPU 成本 0.0522562、估計行數 52256 和實際行數 52251。但是在之前的計劃中,相同的函式現在 實際行數為 327605402,這是一個巨大的差異。

我執行了 Paul Randal 的擴展事件會話,它根據他的建議跟踪特定會話的等待類型,並得到以下輸出:

Wait Type            Count Total Wait (ms)  Resource Wait (ms)  Signal Wait (ms)
NETWORK_IO            4807            1119                1119                0
CXPACKET              9449             649                 620               29
SOS_SCHEDULER_YIELD 119763             370                   0              370
SLEEP_TASK           11212               2                   0                2
LATCH_EX               782               1                   1                0
LATCH_SH                 2               0                   0                0
LCK_M_S                  4               0                   0                0
EXECSYNC                 3               0                   0                0
PAGEIOLATCH_EX           4               0                   0                0
PAGELATCH_EX             1               0                   0                0
PAGELATCH_SH             7               0                   0                0
PAGELATCH_UP            55               0                   0                0

請注意,等待時間很少,但 CPU 時間幾乎與持續時間相匹配。Paul 提到這可能是自旋鎖爭用,但是我們在 SQL 2014 SP1 CU2 上執行,並且錯誤https://support.microsoft.com/en-ca/kb/3026083已在 SP1 中修復。同樣,在 system_health.xel 上看不到任何內容。

sys.databases本身的查詢總是很快的。

…為什麼加入 sys.databases 會對性能造成巨大影響?為什麼不一致?

加入sys.databases並沒有什麼特別之處。優化器碰巧選擇了一個對第一個查詢效率低的計劃。具體而言,在該計劃領域:

計劃片段

…優化器選擇一個嵌套循環連接到SYSDMEXECCACHEDPLANS,大概是基於對連接的外部輸入上極少數驅動行的期望(來自合併連接)。優化器引入了一個表假離線來降低嵌套循環連接的外部輸入上的任何重複值的處理成本,但這不太可能非常有效 - 雜湊連接會“更好”。

..相同的函式現在實際行數為 327605402,這是一個巨大的差異。

這是在 SSMS 中讀取執行計劃時的常見錯誤(SQL Sentry 的計劃資源管理器不會遇到此問題)。在 SSMS 中,嵌套循環連接內側的估計行數顯示為每次迭代,而實際行數顯示在所有迭代中。這是“有問題的設計決定”的結果。

因此,性能不佳的根本原因很可能僅僅是掃描所有記憶體計劃的完整集而不是優化器預期的次數。掃描整個記憶體6269 次會很慢(除非當時記憶體很小)。

基數估計錯誤不僅僅發生在使用者表中,所以這並不奇怪。不要把它專門歸咎於sys.databases。“額外的連接”或“對謂詞的輕微更改”對計劃選擇產生巨大影響是很常見的。

幫助優化器查詢系統表、視圖和函式的選項比平常少。對於專家分析師來說,提示可能是適當的解決方案。在其他情況下,最好將查詢分解為多個步驟。在您的情況下,根據提供的資訊,簡單地用元數據函式替換“額外連接”似乎就足夠了。

SOS_SCHEDULER_YIELD 積累就像我在#sqlhelp 上建議的那樣。這些中的每一個都相當於查詢的 4 毫秒 CPU 時間,並且它們始終顯示零資源等待時間,因為不涉及資源等待(執行緒讓出處理器並直接進入調度程序上可執行隊列的底部)。

所以 - 這個查詢在不需要任何其他資源的情況下通過 CPU 攪動。

這也與自旋鎖無關,因為它們不會顯示為特定的等待類型(常見的誤解是 SOS_SCHEDULER_YIELD = 自旋鎖)。我建議當你說沒有任何等待累積時。

當它執行緩慢時,它返回的行數是否比快速執行時明顯多?

引用自:https://dba.stackexchange.com/questions/138929