Sql-Server

只讀副本上的長時間執行查詢,在主副本上需要一些時間

  • May 10, 2019

我有一個 4 節點 AG 設置,如下所示:

所有節點的VM硬體配置:

  • Microsoft SQL Server 2017 企業版 (RTM-CU14) (KB4484710)
  • 16 個 vCPU
  • 356 GB RAM(長篇大論……)
  • 最大並行度:1(根據應用供應商的要求)
  • 並行性的成本門檻值:50
  • 最大伺服器記憶體 (MB):338944 (331 GB)

AG 配置:

  • 節點 1:主節點或同步送出不可讀輔助節點,配置為自動故障轉移
  • 節點 2:主節點或同步送出不可讀輔助節點,配置為自動故障轉移
  • 節點 3:具有非同步送出的可讀輔助集,配置為手動故障轉移
  • 節點 4:具有非同步送出的可讀輔助集,配置為手動故障轉移

有問題的查詢:

這個查詢並沒有什麼特別瘋狂的地方,它提供了應用程序中各個隊列中未完成工作項的摘要。您可以從下面的執行計劃連結之一查看程式碼。

主節點上的執行行為:

在 Primary 節點上執行時,執行時間一般在 1 秒左右。這是執行計劃,下面是從主節點的 STATISTICS IO 和 STATISTICS TIME 擷取的統計資訊:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

SQL Server Execution Times:
  CPU time = 500 ms,  elapsed time = 656 ms.
SQL Server parse and compile time: 
  CPU time = 0 ms, elapsed time = 0 ms.

只讀輔助節點上的執行行為:

在任一隻讀輔助節點(即節點 3 或節點 4)上執行時,此查詢使用相同的執行計劃(這是不同的計劃連結)並顯示大致相同的執行統計資訊(例如,可能還有更多頁面掃描,因為這些結果總是在變化),但除了 CPU 時間之外,它們看起來非常相似。以下是從只讀輔助節點的 STATISTICS IO 和 STATISTICS TIME 擷取的統計資訊:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

SQL Server Execution Times:
  CPU time = 55719 ms,  elapsed time = 56335 ms.
SQL Server parse and compile time: 
  CPU time = 0 ms, elapsed time = 0 ms.

其他詳情:

在執行此查詢時,我還在輔助伺服器上同時執行了sp_WhoIsActivePaul Randal 的WaitingTasks.sql腳本,但我沒有看到任何等待發生的情況,坦率地說,這令人沮喪:

在此處輸入圖像描述

這看起來也不是 AG 延遲的情況,因為 Synchronization 狀態實際上非常好:

--https://sqlperformance.com/2015/08/monitoring/availability-group-replica-sync

SELECT 
      ar.replica_server_name, 
      adc.database_name, 
      ag.name AS ag_name, 
      drs.is_local, 
      drs.synchronization_state_desc, 
      drs.synchronization_health_desc, 
      --drs.last_hardened_lsn, 
      --drs.last_hardened_time, 
      drs.last_redone_time, 
      drs.redo_queue_size, 
      drs.redo_rate, 
      (drs.redo_queue_size / drs.redo_rate) / 60.0 AS est_redo_completion_time_min,
      drs.last_commit_lsn, 
      drs.last_commit_time
FROM sys.dm_hadr_database_replica_states AS drs
INNER JOIN sys.availability_databases_cluster AS adc 
      ON drs.group_id = adc.group_id AND 
      drs.group_database_id = adc.group_database_id
INNER JOIN sys.availability_groups AS ag
      ON ag.group_id = drs.group_id
INNER JOIN sys.availability_replicas AS ar 
      ON drs.group_id = ar.group_id AND 
      drs.replica_id = ar.replica_id
ORDER BY 
      ag.name, 
      ar.replica_server_name, 
      adc.database_name;

在此處輸入圖像描述

這個查詢似乎是最嚴重的違規者。在主節點上也需要亞秒級時間的其他查詢在輔助節點上可能需要 1 到 5 秒,雖然行為不那麼嚴重,但它看起來確實會導致問題。

最後,我還查看了伺服器並檢查了外部程序,例如 A/V 掃描、產生意外 I/O 的外部作業等,但都空手而歸。我不認為這是由 SQL Server 程序之外的任何東西引起的。

問題:

我現在才中午,而且已經是漫長的一天,所以我懷疑我在這裡遺漏了一些明顯的東西。要麼是這樣,要麼是我們配置錯誤,這是可能的,因為我們已經多次呼叫與此環境相關的供應商和 MS。

對於我所有的調查,我似乎無法找到導致這種性能差異的原因。我希望在輔助節點上看到某種等待,但什麼也沒有。如何進一步解決此問題以確定根本原因?有沒有人見過這種行為並找到解決方法?

更新 #1 在將第三個節點(只讀副本之一)的狀態交換為不可讀,然後作為測試返回為可讀後,該副本仍被打開的事務佔用,任何客戶端查詢都顯示HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONING等待。

執行DBCC OPENTRAN命令會產生以下結果:

Oldest active transaction:
   SPID (server process ID): 420s
   UID (user ID) : -1
   Name          : QDS nested transaction
   LSN           : (941189:33148:8)
   Start time    : May  7 2019 12:54:06:753PM
   SID           : 0x0
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

在 中查找此 SPID 時sp_who2,它會將其顯示為一個BACKGROUND程序,QUERY STORE BACK並以命令的形式列出。

雖然我們能夠進行 TLog 備份,但我懷疑我們遇到了這個已解決錯誤的類似功能,所以我計劃今天就這個特定問題向 MS 開一張票。

根據該票的結果,我將嘗試根據 Joe 的建議擷取呼叫堆棧跟踪,然後看看我們要去哪裡。

最終更新(問題自行解決)

在超過 Query Store 事務打開的 52 小時標記之後(如上所述),AG 決定自動進行故障轉移。在這發生之前,我確實提取了一些額外的指標。根據Sean 提供的這個連結,有問題的數據庫有一個非常大的版本儲存專用於該數據庫,特別是在某一時刻,我在該reserved_page_count欄位中記錄了 1651360 個頁面和 13210880 個reserved_space_kb值。

QDS base transaction根據錯誤日誌,故障轉移是在與事務相關的事務強化失敗 5 分鐘後發生的QDS nested transaction

就我而言,故障轉移確實導致了大約 10 分鐘的中斷。該數據庫的大小約為 6TB,並且非常活躍,因此在我看來這實際上非常好。雖然新的主節點在此期間線上,但沒有客戶端查詢可以完成,因為它們都在等待QDS_LOADDB等待類型。

故障轉移後,版本儲存數量減少到 176reserved_page_count和 1408 reserved_space_kb。對輔助只讀副本的查詢也開始像從主副本執行一樣快地執行,因此看起來該行為完全消失了,這是故障轉移的結果。

這個答案是喬的答案的補充,因為我不能 100% 確定它是版本儲存,但是到目前為止有足夠的證據表明這是問題的一部分。

當輔助副本被標記為可讀時,首先需要獲得版本控制資訊的良好穩定狀態,以便輔助副本上的所有讀取操作都有一個已知且良好的起點。當它正在等待轉換並且主伺服器上仍有未處理的事務時,這將表現為HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONING並且也是一個很好的指標,表明主伺服器確實經歷了相當多的數據流失(或者至少有人有一個非常長的未處理事務也不好)。事務打開的時間越長,數據更改越多,版本控制就越多。

次要副本通過在會話的封面下使用快照隔離來實現可讀狀態,即使您檢查會話資訊,您也會看到它顯示在預設的讀取送出時。由於快照隔離是樂觀的並使用版本儲存,因此所有更改都需要進行版本控制。當輔助節點上有許多正在執行(並且可能長時間執行)的查詢而主節點上的數據流失率很高時,這種情況會更加嚴重。通常,這僅體現在 OLTP 系統的幾個表中,但它完全取決於應用程序和工作負載。

版本儲存本身以代為單位進行測量,當執行需要使用版本儲存的查詢時,版本控制記錄指針用於指向該行的 TempDB 鏈。我說鏈,因為它是該行的版本列表,並且必須按順序遍歷整個鏈以根據事務的起始時間戳找到正確的版本,以便結果與給定時間的數據內聯。

如果版本儲存由於主副本和輔助副本上的長時間執行事務而對這些行有很多代,這將導致查詢執行的時間比平均時間長,並且通常以更高的 CPU 形式執行,而所有其他項目似乎保持完全相同- 比如執行計劃、統計資訊、返回的行數等。鏈的遍歷幾乎是一個純粹的cpu操作,所以當鏈變得很長並且返回的行數很高時,你得到一個(不是線性的,而是可以關閉)查詢的時間增加。

唯一可以做的是限制主要和次要事務的長度,以確保版本儲存在 TempDB 中不會變得太大,同時有很多代。清理版本儲存的嘗試大約每分鐘發生一次,但是清理要求在刪除之前不再需要同一代的所有版本,並且在不再需要最舊的版本之前無法清理所有未來的版本。因此,長時間執行的查詢可能導致無法有效地清理許多未使用的代。

切換副本進入和退出可讀模式也將清除版本儲存,因為它不再可讀。

還有其他項目也可能在起作用,但考慮到目前數據和復製品的反應方式,這似乎是最合理的。

TempDB 版本控制 DMV(不要與 ADR 版本控制混淆)。

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