事務複製會話

原文地址：

https://blogs.msdn.microsoft.com/chrissk/2009/05/25/transactional-replication-conversations/

修訂版：

https://blogs.msdn.microsoft.com/repltalk/2010/02/21/transactional-replication-conversations/

事物複製會話

當定位事物複製性能，將數據流拆分爲4個同步會話。檢查每一個會話的性能。這將幫助驗證應該從哪開始調查性能瓶頸。

1） 日誌讀取器讀線程經過存儲過程sp_replcmds（xp_replcmds的一個包裝）讀取事物日誌。它掃描事物日誌查找標記爲複製的事物，跳過未複製的事物。

2） 日誌讀取器寫線程使用sp_MSadd_replcmds將事物從讀取線程放到Distribution數據庫的隊列中。

3） 分發讀線程執行sp_MSget_repl_commands查詢來從Distribution數據庫獲取命令並存儲到一個內部隊列中。

4） 分發寫線程經過前綴sp_MSupd…、sp_MSins…參數化存儲過程寫隊列命令到訂閱者，在訂閱者應用獨立的行修改到每一個文章。

5） 日誌讀取器和分發器也執行一個歷史線程寫摘要數據到Distribution數據庫的MSlogreader_history和MSdistribution_history系統表。

定位性能問題的輔助工具

SQL Profiler：有多種方法詳細檢查事務複製會話。對全部鏈接到SQL Server的應用，被複制組件執行的命名能夠被SQL Profiler捕獲到。跟蹤能夠被存儲或查詢來找出慢查詢。

你能夠找到的ApplicationName的示例：

• REPLICATION MONITOR – SSMS裏的GUI工具

• REPL-LOGREADER-#-DatabaseName-# -- 日誌讀取器代理的寫線程記錄修改到分發表。

• ServerName\Instance-DatabaseName-PubName-Subscriber – 分發代理的讀線程找出哪些命令/事務複製到訂閱者

• REPLICATION LOGREAD HISTORY – 日誌讀取器代理的寫線程記錄日誌歷史

• REPLICATION DISTRIBUTION HISTORY – 分發代理的寫線程記錄日誌歷史

複製的存儲過程調用示例：

• Distribution Activity：

• 
  

  • SP_MSGET_REPL_COMMANDS

  • SP_MSHELP_DISTRIBUTION_AGENTID

  • SP_MSGET_SUBSCRIPTION_GUID

• LogReader Activity：

• 
  

  • SP_MSADD_REPLCMDS

  • SP_MSADD_LOGREADER_HISTORY

  • SP_REPLCMDS

  • SP_MSPUB_ADJUST_IDENTITY

  • EXEC SP_MSGET_LAST_TRANSACTION @PUBLISHER_ID = {##}, @PUBLISHER_DB = {STRN}, @FOR_TRUNCATE = {BS}

  • SP_REPLDONE

  • EXEC SP_REPLCOUNTERS {STRN}

• SubScriber Activity：

• 
  

  • SP_MSins%

  • SP_MSupd%

  • SP_MSdel%

Activity Monitor：SSMS的Activity Monitor，SQL Server 2005性能面板，SQL Server 2008性能數據倉庫，或者系統存儲過程幫助找到阻塞、磁盤瓶頸，和致使高IO和高CPU的語句。爲了幫助識別複製組件查找鏈接到SQL Server的日誌讀取器代理或分發代理做業名像Program_Name。來看一個複製做業的列表，運行如下查詢：

SELECT name, description, enabled from MSDB..sysjobs
WHERE category_id>10 and category_id<20

Tracer Tokens：在Replication Monitor中使用Tracer Token特性來得到一個複製性能的快速高級別的概覽。該特性提供了「Publisher to Distributor」和「Distributor to Subscriber」延遲值。爲了使用這個特性，開啓Replication Monitor。在My Publishers列表中，進一步點擊你但願測試的發佈。在右邊的面板中，選擇Tracer Token標籤並點擊「Insert Tracer Token」按鈕。在下面會有一個訂閱列表。監控「Publisher to Distributor」和「Distributor to Subscriber」值。

該方法只對近乎實時的狀況有幫助。若是該拓撲結構超過3天，那麼你將毫不會及時看到訂閱者上的Tracer Token，所以你能夠看到的惟一的事是--是否Log Reader跟上或落後了。那仍舊是有價值的信息，可是更日常，若是訂閱者只落後5分鐘而且你能夠看到從開始到完成的完整Token軌跡。

若是你看到「Publisher to Distributor」產生很長時間，着眼於排查日誌讀取器性能。若是日誌讀取器性能快而「Distributor to Subscriber」值高，事務從發佈數據庫事務日誌快速移動到分發數據庫，可是從分發數據庫到訂閱者較慢。分發代理應該是調查瓶頸的焦點。

如下連接提供了衡量時間延遲的示例代碼。

• http://www.replicationanswers.com/TracerTokens.asp

• https://www.mssqltips.com/sqlservertip/2258/monitor-sql-server-replication-latency-using-tracer-tokens/

• http://www.microsoft.com/technet/prodtechnol/sql/2005/p2ptranrepl.mspx

Performance Monitor：你也可使用Windows Performance Monitor來跟蹤複製日誌讀取器計數器「LogReader:Delivery Latency」或者複製分發計數器「Dist:Delivery Latency」。然而，Windows Performance監視器的複製計數器值，只在日誌讀取器或者分發代理完成了一個處理階段並記錄了性能統計信息後才更新。計數器值將報告0個commands/sec和transactions/sec而組成百萬行的大型事務正被處理。

日誌讀取器線程Reader-Thread延時

常規排查方法：

添加「-OUTPUT」參數到日誌讀取器，將時間分解爲讀取（獲取時間），和寫入（寫入時間）會話。在如下示例輸出中Reader-Thread花了55分鐘而Writer-Thread只須要3分鐘來處理事務，說明了日誌讀取器線程Reader-Thread是瓶頸。

複製的日誌讀取器代理

http://msdn.microsoft.com/en-us/library/ms146878.aspx

******************** STATISTICS SINCE AGENT STARTED ***************************
Execution time (ms): 3401930
Work time (ms): 3401470
Distribute Repl Cmds Time(ms): 3354520
Fetch time(ms): 3343920 <– read time 55 minutes
Repldone time(ms): 5520
Write time(ms): 140070 <– write time 3 minutes
Num Trans: 8 Num Trans/Sec: 0.002352
Num Cmds: 477219 Num Cmds/Sec: 140.297871
*******************************************************************************

從如下SQL Server版本開始，日誌讀取器代理統計信息每5分鐘顯示，並寫入到分發數據庫的MSlogreader_history表。

• Cumulative Update 12 for SQL Server 2005 Service Pack 2

• Cumulative Update 5 for SQL Server 2008

• Cumulative Update 2 for SQL Server 2008 Service Pack 1

可能緣由：大批覆制的事務

對於發佈數據庫的事務日誌有多大？它是否增加到一個沒法預期的大小，致使日誌讀取器線程更長讀取時間。

DBCC SQLPERF(LOGSPACE)

日誌讀取器讀線程執行sp_replcmds從事務日誌拉取命令。如下存儲過程能夠在SSMS中執行來跟蹤須要拉取下一個複製的事務日誌的時間。這些命令執行花費多久？返回多少命令？掃描一個大的事務日誌，單個事務包含一百萬多行修改可能花費20多分鐘完成。這個查詢的執行時間接近日誌讀取器複製這個相同事務的啓動時間。

顯示第一個事務元數據像publication_id、article id、xactid和command_type。這個命令是不是常規數據庫操做的一部分或者一個沒法預計的大批量的命令？

sp_replcmds [ @maxtrans = ] maxtrans

http://msdn.microsoft.com/en-us/library/ms186983.aspx

示例：

-- Return all commands from the next pending transaction
sp_replcmds @maxtrans = 1
GO
-- Return all commands for the next 500 transactions
sp_replcmds @maxtrans = 500
GO
sp_replflush
GO

顯示第一個事務元數據以及還沒有複製的命令文本。Commands type = 1073741871是接下來的Tracer Tokens。

sp_replshowcmds [ @maxtrans = ] maxtrans

http://msdn.microsoft.com/en-us/library/ms175114.aspx

示例：

-- Return all commands from the next pending transaction with CMD text
sp_replshowcmds @maxtrans = 1
GO
-- Return all commands for the next 500 transactions with CMD text
sp_replshowcmds @maxtrans = 500
GO
sp_replflush
GO

另外一個查看接下來一批transactions/commands的摘要信息的方法是查詢sys.dm_repl_traninfo視圖。這顯示了被sp_replcmds或sp_replshowcmds最後讀取的日誌中的複製事務的摘要數據，包括「cmds_in_tran」。一個大的值可能代表一個大事務正被複制。

sys.dm_repl_traninfo

http://msdn.microsoft.com/en-us/library/ms180036.aspx

sp_replcmds @maxtrans = 500 -- retrieve 500 pending transactions
GO
SELECT dbid, begin_lsn, commit_lsn, rows, cmds_in_tran
FROM sys.dm_repl_traninfo
GO

dbid begin_lsn commit_lsn rows cmds_in_tran
—— ——————————– ——————————– ———– ————
10 0000081A:0000013A:0001 0000081A:0000013A:0004 1 1
10 0000081A:00000140:0001 0000081A:00000140:0004 1 1
10 0000081A:00021385:0001 0000081E:00004EA2:0009 6874 6874

下面的命令能夠用於肯定不復制和複製事務的數量。具備高百分比的不復制事務的一個事務日誌會致使延時，由於日誌讀取器掃描過將被忽略的事務。這些多是數據庫維護事務，像在線重建索引或者對錶的數據修改不會被複制。一個25GB事務日誌根據IO子系統可能要花費15分鐘掃描。

Use <published database>
GO
-- Total records in the log
SELECT count(*) FROM ::fn_dblog(NULL, NULL)
GO
-- Records marked for REPLICATION
SELECT count(*) FROM ::fn_dblog(NULL, NULL) WHERE Description=‘REPLICATE’
GO

若是正處理sp_replcmds時捕獲了大事務，你也能夠在SQL Profiler跟蹤數據的那個事件中看到長時運行時間。如下使用一個捕獲的Profiler跟蹤運行命令來查詢結果：

SELECT duration, starttime, endtime, textdata
FROM ::fn_trace_gettable(‘C:\PUBLISHERDB_sp_trace.trc’, DEFAULT)
WHERE TEXTDATA LIKE ‘%SP_REPLCMDS%’ AND EVENTCLASS=10

Duration StartTime EndTime TextData
388 2008-10-21 15:00:06.010 2008-10-21 15:00:06.010 exec sp_replcmds 500,0,-1,0x,5000,0,500000
393 2008-10-21 15:00:11.010 2008-10-21 15:00:11.010 exec sp_replcmds 500,0,-1,0x,5000,0,500000
397 2008-10-21 15:00:16.010 2008-10-21 15:00:16.010 exec sp_replcmds 500,0,-1,0x,5000,0,500000
66302488 2008-10-21 15:00:21.010 2008-10-21 15:01:27.290 exec sp_replcmds 500,0,-1,0x,5000,0,500000
413 2008-10-21 15:01:27.353 2008-10-21 15:01:27.353 exec sp_replcmds 500,0,-1,0x,66344,0,500000

如上所示，處理大事務致使sp_replcmds執行花費66秒。

解決方案：

若是由大量命令致使的讀取延時，等待日誌讀取器跟上多是最佳短時間解決方案。長期來說，在非高峯期複製批處理或者以存儲過程執行。

在事務複製中發佈存儲過程執行

http://msdn.microsoft.com/en-us/library/ms152754(SQL.90).aspx

另外一個方法是考慮配置日誌讀取器，將一個大事務拆分爲多個批處理。經過以更小的批處理來提交大事務，咱們能夠減小日誌讀取器總開銷。然而，當以多個並行流分發數據到訂閱者，性能提升最值得注意。

複製日誌讀取器代理

http://msdn.microsoft.com/en-us/library/ms146878.aspx

依賴預估的時間來讀取事務並傳輸到訂閱者，它會比將事務標記爲「已複製」更快，而後使用一個新的快照或者經過備份/恢復來初始化訂閱者。若是生成一個新的複製快照並傳遞給訂閱者比等待單個命令被複制更快，這是惟一須要採起的步驟。

sp_repldone (Transact-SQL)

http://msdn.microsoft.com/en-us/library/ms173775.aspx

EXEC sp_repldone @xactid = NULL, @xact_segno = NULL, @numtrans = 0, @time = 0, @reset = 1

可能緣由：大量不復制的事務

識別這個可能更具挑戰性。對於精通哪些文章被複制，什麼批修改當前已被複制有幫助。在Profile Trace中的BINARY列代表被sp_replcmds處理的行數。使用少許行的屢次執行一般代表日誌讀取器花費時間掉過不復制的事務，像大表執行在線索引重建。

來自日誌讀取器日誌的如下輸出清晰的顯示了不少行被讀取，而只有一些被複制。

2008-11-11 23:41:35.527 The Log Reader Agent is scanning the transaction log for commands to be replicated. Approximately 500000 log records have been scanned in pass # 3, 142 of which were marked for replication, elapsed time 22535010 (ms).

解決方案：

當對於不復制的表有大量的事務，這是不可避免的。若是問題是因爲索引維護日誌記錄致使，考慮執行離線重建索引。另外一個方法是中止並開始在線重建索引來建立更小的索引更新事務的批處理。

可能緣由：大量VLFs

大量的虛擬日誌文件（VLFs）會致使日誌讀取器讀取時間更長。爲了肯定VLFs的數量，執行如下命令並注意返回的段（行）數量。段數量在100K以上會致使日誌讀取器Reader-Thread性能問題。

USE <published DB>
GO
DBCC LOGINFO

解決方案：

收縮事務日誌來移動額外的VLFs。設置數據庫「growth」到容許增加而不用建立大量VLFs的值。

907511 在SQL Server 2005中如何使用DBCC SHRINKFILE語句來收縮事務日誌文件

http://support.microsoft.com/default.aspx?scid=kb;EN-US;907511

可能緣由：慢讀取IO

慢的磁盤子系統會致使讀取時間長。比較好的衡量磁盤讀取性能的是Windows Performance Monitor計數器Avg Disk Sec/Read。

解決方案：

讀取時間大於15ms可能代表有IO讀取瓶頸，應該讓存儲子系統的供應商調查。

可能緣由：慢網絡IO

對於使用拉取的日誌讀取器的遠程分發器，logread.exe執行在分發器，可是從發佈事務日誌拉取行集。沒法預計的網絡IO問題會致使Reader-Thread延時。

解決方案：

使用Windows Performance Monitor監視發佈和分發服務器，檢查活動的網絡適配器的「Output Queue Length」計數器—這個計數器應該持續在2如下。

對於更多信息請查看如下MSDN標題「網絡適配器對象」。

http://msdn.microsoft.com/en-us/library/ms803962.aspx

日誌讀取器線程Writer-Thread延時

可能緣由：阻塞

對於日誌讀取器代理-OUTPUT日誌中「Write time(ms):」值較大，代表寫入命令到分發數據庫有瓶頸。可能由另外一個SQL複製代理，像分發清理代理致使阻塞。使用SQL Server內嵌的工具像SSMS的Activity Monitor、性能面板、性能數據倉庫或存儲過程像sp_who，來調查由日誌讀取器Writer-Thread致使的阻塞。

對於SQL Server 2005，下載並安裝性能面板。這提供了一個高級別的堆分發器性能的查看。阻塞、慢查詢、高IO等待時間以圖形化顯示。對於SQL Server 2008，這些報表包含在性能數據倉庫。

SQL Server 2005性能面板報表

http://www.microsoft.com/downloads/details.aspx?familyid=1d3a4a0d-7e0c-4730-8204-e419218c1efc&displaylang=en

解決方案：

若是阻塞的源頭是分發清理，考慮中止這個代理，容許數據被複制，而後在非高峯時間重啓清理。阻塞可能代表IO須要比預期更長時間完成。對於其餘排查步驟，查看「高IO」。

可能緣由：高IO

檢查在分發器上收集的針對sp_MSadd_replcmds執行的Duration和CPU值的Profile跟蹤。

高IO可能代表糟糕的查詢計劃。使用如下命令行對於完成的事件使用一個捕獲的Profile跟蹤讀取CPU和Duration。

SELECT duration, starttime, endtime, textdata
FROM ::fn_trace_gettable(‘C:\DISTRIBUTOR_sp_trace.trc’, DEFAULT)
WHERE TEXTDATA LIKE ‘%SP_MSadd_replcmds%’ AND EVENTCLASS=10

Durations是CPU時間的10倍以上代表資源爭用。在分發器上運行SSMS報表查找日誌讀取器代理的阻塞。

使用SQL Server 2005和2008系統視圖也能夠用於獲取對於日誌讀取器Writer-Thread的Duration和CPU值。低Duration和CPU可是高邏輯讀代表因爲數據表統計信息致使的槽糕查詢計劃。如下命令會得到查詢計劃以及執行統計信息。

-- dm_exec_query_stats for Log Reader Writer-Thread sp_MSadd_replcmds
-- by top total_worker_time
SELECT TOP 25
st.text, qp.query_plan,
(qs.total_logical_reads/qs.execution_count) as avg_logical_reads,
(qs.total_logical_writes/qs.execution_count) as avg_logical_writes,
(qs.total_physical_reads/qs.execution_count) as avg_phys_reads,
qs.*
FROM sys.dm_exec_query_stats as qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as st
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) as qp
WHERE st.text like ‘CREATE PROCEDURE sp_MSadd_replcmds%’
ORDER BY qs.total_worker_time DESC
Go

可能緣由：慢寫入IO

慢磁盤子系統會致使寫入時間長。比較好的衡量磁盤讀性能的方法是Windows Performance Monitor計數器Avg Disk Sec/Write。

解決方案：

寫入時間大於20毫秒可能代表IO寫入瓶頸，應該讓存儲子系統供應商調查。

可能緣由：網絡IO

相似於以上狀況，你會想去調查網絡適配器確認隊列長度。

分發代理讀取延時

就像日誌讀取器，分發代理是兩個同時進行的會話。從分發器到訂閱者移動行的延時會發生在這些會話。Reader-Thread會話負責查詢分發數據庫對於事務列表應用到訂閱者。它首先查詢訂閱者元數據表來找到最後成功複製的事務。接下來Reader-Thread執行sp_MSget_repl_commands來開始從分發數據庫讀取行，並生成行到一個內存隊列。對於隊列中的行，分發代理Writer-Thread會話開始寫這些行到訂閱者。就像使用日誌讀取器，添加分發代理-OUTPUT參數會提供較好的分發代理性能的回顧。如上所述，當前的SQL Server如今自動在分發代理歷史表MSdistribution_history記錄這個信息。

在這個輸出中，READS以565cmds/sec的速度完成，而WRITES花費了14000ms（14秒）而且只處理3.69cmds/sec。這個示例清晰的顯示了寫入比讀取更慢。

************************ STATISTICS SINCE AGENT STARTED ***********************
Total Run Time (ms) : 18828 Total Work Time : 14110
Total Num Trans : 52 Num Trans/Sec : 3.69
Total Num Cmds : 52 Num Cmds/Sec : 3.69
Writer Thread Stats
Time Spent on Exec : 12063
Time Spent on Commits (ms): 422 Commits/Sec : 0.14
Time to Apply Cmds (ms) : 14110 Cmds/Sec : 3.69 <– Write Thread
Time Cmd Queue Empty (ms) : 671 Empty Q Waits > 10ms: 2
Total Time Request Blk(ms): 671
Reader Thread Stats
Calls to Retrieve Cmds : 2
Time to Retrieve Cmds (ms): 92 Cmds/Sec : 565.22 <– Reader Thread
Time Cmd Queue Full (ms) : 5486 Full Q Waits > 10ms : 3
*******************************************************************************

可能緣由：大批事務

延時問題一般當一系列事務嘗試移動大批命令到訂閱者致使。如下查詢顯示了總體行計數和存儲在分發數據庫的命令的索引統計信息。

-- ROW COUNTS
-- Look for high row counts (>1millions) indicate cleanup not running
-- or large pending transactions.
SELECT name, rowcnt, STATS_DATE (id, indid) as ‘Last Update Stats’
FROM distribution.dbo.sysindexes
WHERE name IN(‘ucMSrepl_transactions’, ‘ucMSrepl_commands’)

這個行計數是不是預期值，或者如今包含數百萬行？高的行計數（大於1百萬）可能代表一個大事務正在處理或者清理進程沒有運行。

當經過天天查看多個命令來排查性能延時問題不是一個好方法。存儲在分發數據庫的命令的分析能夠經過運行以下命令獲取。

-- Check the Time associated with those Transaction Counts into temp table
select t.publisher_database_id, t.xact_seqno,
max(t.entry_time) as EntryTime, count(c.xact_seqno) as CommandCount
into #results
FROM MSrepl_commands c with (nolock)
LEFT JOIN msrepl_transactions t with (nolock)
on t.publisher_database_id = c.publisher_database_id
and t.xact_seqno = c.xact_seqno
GROUP BY t.publisher_database_id, t.xact_seqno
-- Show each hour and number of commands per Day:
SELECT publisher_database_id
,datepart(year, EntryTime) as Year
,datepart(month, EntryTime) as Month
,datepart(day, EntryTime) as Day
,datepart(hh, EntryTime) as Hour
--,datepart(mi, EntryTime) as Minute
,sum(CommandCount) as CommandCountPerTimeUnit
FROM #results
GROUP BY publisher_database_id
,datepart(year, EntryTime)
,datepart(month, EntryTime)
,datepart(day, EntryTime)
,datepart(hh, EntryTime)
--,datepart(mi, EntryTime)
-- order by publisher_database_id, sum(CommandCount) Desc
ORDER BY publisher_database_id, Month, Day, Hour

在如下示例輸出中，大批量的事務被複制，結果表更新在分發代理中致使速度減緩。

publisher_database_id Year Month Day Hour CommandCountPerTimeUnit
——————— ———– ———– ———– ———– ———————–
2 2009 5 14 10 132
2 2009 5 14 11 656
2 2009 5 14 12 880
2 2009 5 14 13 4379
2 2009 5 14 14 152
2 2009 5 14 15 1478
2 2009 5 14 20 161
2 2009 5 14 21 145
2 2009 5 15 6 1700
2 2009 5 15 7 3672
2 2009 5 15 8 6266
2 2009 5 15 9 329
2 2009 5 15 10 5678715
2 2009 5 15 11 5637959
2 2009 5 15 12 5281732
2 2009 5 15 13 5020950
2 2009 5 15 14 1252
2 2009 5 16 11 732
2 2009 5 16 12 178
2 2009 5 16 13 725
2 2009 5 16 14 186
2 2009 5 16 16 72

解決方案：

在分發數據庫的分發代理Reader-Thread須要對大批量的事務請求大量IO。快速的磁盤子系統對事務日誌和數據裏在獨立的驅動/LUNs能夠幫助提升IO性能。若是這是一個正在進行的模式，考慮複製存儲過程EXECUTION代替RESULTS。

在事務複製中發佈存儲過程執行

http://msdn.microsoft.com/en-us/library/ms152754(SQL.90).aspx

排查讀線程：在讀取線程中的分發代理延時發生在從DistributionDB獲取行集。得到代理歷史或者-OUTPUT並檢查每5分鐘產生的代理統計信息。

************************ STATISTICS SINCE AGENT STARTED ***********************
03-22-2009 09:55:19
Total Run Time (ms) : 59189906 Total Work Time : 492741
Total Num Trans : 5 Num Trans/Sec : 0.01
Total Num Cmds : 5 Num Cmds/Sec : 0.01
Total Idle Time : 58660470
Writer Thread Stats
Total Number of Retries : 0
Time Spent on Exec : 0
Time Spent on Commits (ms): 16 Commits/Sec : 0.05
Time to Apply Cmds (ms) : 0 Cmds/Sec : 0.00
Time Cmd Queue Empty (ms) : 528717 Empty Q Waits > 10ms: 5
Total Time Request Blk(ms): 59189187
P2P Work Time (ms) : 0 P2P Cmds Skipped : 0
Reader Thread Stats
Calls to Retrieve Cmds : 11738
Time to Retrieve Cmds (ms): 492741 Cmds/Sec : 0.01
Time Cmd Queue Full (ms) : 0 Full Q Waits > 10ms : 0
*******************************************************************************

來自分發代理日誌的-OUTPUT顯示了100%的Duration花費在代理中止以前從分發數據庫讀取行。

當事件完成時代理日誌也記錄時間。在如下示例中，持續了4分鐘，在分發代理查詢訂閱者對開始複製的事務的時間和它從分發數據庫獲取批量事務的時間之間。讀取線程致使的延時，等待從DistributionDB返回的命令。

-- Example from Distribution Agent -OUTPUT showing delay in READER thread.
-- Read for Subscription metadata completes
2009-05-16 01:26:49.229 OLE DB Distributor ‘SQL380’: {call sp_MSget_subscription_guid(11)}
-- Four minutes later read of replication cmds completes.
2009-05-16 01:29:31.401 sp_MSget_repl_commands timestamp value is: 0x0x0000081a00000045000400000000
-- Reader threads are waiting for CMDs to be returned from the Distribution DB.

爲了測試讀取執行時間，從查詢窗口運行sp_MSget_repl_commands，查看阻塞、表掃描、超時等。

1. 從-OUTPUT對於長時間運行的sp_MSget_repl_commands得到LSN

2009-05-16 01:29:31.401 sp_MSget_repl_commands timestamp value is: 0x0x0000081a00000045000400000000

2. 從相同的日誌得到Agent_ID

3. 對DistributionDB執行sp_MSget_repl_commands

sp_MSget_repl_commands @agent_id=11, @last_xact_seqno=0x0000081a00000045000400000000

這個命令花費多久執行？是否被阻塞？是否有大量的命令返回？

你也可使用以下查詢從訂閱者的數據庫獲取最後成功的事務。Transaction_timestamp值包含用於存儲過程sp_MSget_repl_commands的LSN。

USE <subscriber db>
-- Retrieve last successful Transaction
-- Multiple rows per publication indicate parallel distribution streams
SELECT publisher,publication, distribution_agent,transaction_timestamp
FROM dbo.MSreplication_subscriptions

對於更多細節，使用如下查詢檢查執行計劃。

USE distribution
GO
DBCC FREEPROCCACHE
DBCC DROPCLEANBUFFERS
SET STATISTICS PROFILE ON
SET STATISTICS IO ON
SET STATISTICS TIME ON
sp_MSget_repl_commands @agent_id=11, @last_xact_seqno=0x0000081a00000045000400000000
SET STATISTICS PROFILE OFF
SET STATISTICS IO OFF
SET STATISTICS TIME OFF

在SQL Server 2005/2008，咱們能夠從DMVs拉取CACHED執行計劃。

-- dm_exec_query_stats for sp_MSget_repl_commands
-- by top total_worker_time
SELECT TOP 25
st.text, qp.query_plan,
(qs.total_logical_reads/qs.execution_count) as avg_logical_reads,
(qs.total_logical_writes/qs.execution_count) as avg_logical_writes,
(qs.total_physical_reads/qs.execution_count) as avg_phys_reads,
qs.*
FROM sys.dm_exec_query_stats as qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as st
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) as qp
WHERE st.text like ‘CREATE PROCEDURE sys.sp_MSget_repl_commands%’
ORDER BY qs.total_worker_time DESC
Go

可能緣由：表統計信息

當事務包含不少小批處理，長時間運行Reader-Thread查詢，可能也代表複製系統表須要更新統計信息。若是AutoUpdateStatistics對分發數據庫禁用，表統計信息會過時。

-- Updated Replication table statistics ‘Updated’ date
DBCC SHOW_STATISTICS(MSrepl_commands,ucMSrepl_commands)
DBCC SHOW_STATISTICS(MSrepl_transactions,ucMSrepl_transactions)
-- Retrieve Distribution database settings
-- Look for IsAutoUpdateStatistics
sp_helpdb distribution
-- or (returns 1)
select DATABASEPROPERTYEX(‘distribution’,‘IsAutoUpdateStatistics’)

解決方案：

-- Updated Replication table statistics
UPDATE STATISTICS MSrepl_transactions
WITH FULLSCAN
UPDATE STATISTICS MSrepl_commands
WITH FULLSCAN

解決方案：

使用內嵌SQL工具，驗證分發代理Reader-Thread沒有在分發數據庫被阻塞。

分發代理寫入延時

Writer-Thread調用複製建立存儲過程對訂閱者應用修改。這些SP以來一個用戶表的惟一索引（一般是主鍵）來定位被更新或刪除的記錄。在寫入線程中延時常在對這些存儲過程的長時間運行執行時間看到。

sp_MSIns_articlename
sp_MSUpd_articlename
sp_MSDel_articlename

可能緣由：

用於應用事務到訂閱者的INS/UPD/DEL存儲過程當中較長執行時間。

在如下示例輸出中，分發代理延時發生在分發代理延時的寫入線程。

-- dm_exec_query_stats for sp_MSupd (Subscriber Updates)
-- by top total_worker_time
SELECT TOP 250
st.text, qp.query_plan,
(qs.total_logical_reads/qs.execution_count) as avg_logical_reads,
(qs.total_logical_writes/qs.execution_count) as avg_logical_writes,
(qs.total_physical_reads/qs.execution_count) as avg_phys_reads,
qs.*
FROM sys.dm_exec_query_stats as qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as st
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) as qp
WHERE st.text like ‘%sp_MSupd_dboemployee%’ — sp_MSupd_dbo<table name>%’
ORDER BY qs.total_worker_time DESC
Go

若是存儲過程已經從緩存刷新或者SQL Server已經重啓，在問題期間在訂閱者上採集的Profile跟蹤將會提供摘要執行數據。一旦被SQL Nexus或者fn_ReadTrace導入，如下存儲過程將總結叫作分發代理的存儲過程。

-- measure ALL spids for performance
select hashid, count(*) as Num, sum(duration) as sumdur, sum(cpu) as sumcpu, sum(reads) as sumreads, sum(writes) as sumwrites, avg(duration) as avgdur, avg(cpu) as avgcpu, avg(reads) as avgreads, avg(writes) as avgwrites
INTO ReadTrace.topCPUBatch
FROM ReadTrace.tblBatches
group by hashid
order by sumcpu desc
GO
-- Get the text for the top CPU batches
select b.*,a.NormText
FROM ReadTrace.tblUniqueBatches a
JOIN ReadTrace.topCPUBatch b
ON a.hashid=b.hashid
where NormText like ‘%SP_MSGET_REPL_COMMANDS%’
-- OR NormText like ‘%SP_MSHELP_DISTRIBUTION_AGENTID%’
-- OR NormText like ‘%SP_MSGET_SUBSCRIPTION_GUID%’
OR NormText like ‘%SP_MSins%’
OR NormText like ‘%SP_MSupd%’
OR NormText like ‘%SP_MSdel%’
order by sumcpu desc

示例輸出

hashid Num sumdur sumcpu sumreads sumwrites avgdur avgcpu avgreads avgwrites NormText
——————– — ——- ———– ———– ———– ——- —— ———– ———– ——————————-
-5684440255897011116 69 966058 389 4071 0 14000 5 59 0 SP_MSGET_REPL_COMMANDS
-2908468862153496396 69 1466258 204 5175 0 21250 2 75 0 SP_MSHELP_DISTRIBUTION_AGENTID
-7220247869142477571 69 539588 31 1152 0 7820 0 16 0 SP_MSGET_SUBSCRIPTION_GUID

可能緣由：

在如下示例輸出中，分發代理延時發生在分發代理延時的寫入線程。

************************ STATISTICS SINCE AGENT STARTED ***********************
Total Run Time (ms) : 18828 Total Work Time : 14110
Total Num Trans : 52 Num Trans/Sec : 3.69
Total Num Cmds : 52 Num Cmds/Sec : 3.69
Writer Thread Stats
Time Spent on Exec : 12063
Time Spent on Commits (ms): 422 Commits/Sec : 0.14
Time to Apply Cmds (ms) : 14110 Cmds/Sec : 3.69
Time Cmd Queue Empty (ms) : 671 Empty Q Waits > 10ms: 2
Total Time Request Blk(ms): 671
Reader Thread Stats
Calls to Retrieve Cmds : 2
Time to Retrieve Cmds (ms): 92 Cmds/Sec : 565.22
Time Cmd Queue Full (ms) : 5486 Full Q Waits > 10ms : 3
*******************************************************************************

在這個輸出中READS以565cmds/sec的速度花費92ms完成，而WRITES花費14000ms（14秒）並只處理了3.69cmds/sec。這個示例清晰的顯示了寫入比讀取慢。

可能緣由：用戶自定義觸發器

在日誌讀取器代理-OUTPUT日誌對於「Write time(ms):」的較大值，代表寫入命令到分發數據庫的瓶頸。一旦可能的緣由是用戶自定義觸發器添加用於調查被其餘複製代理致使的阻塞。

可能緣由：沒有複製SQL語句像「Parameters」

得到建立複製的腳本，並檢查全部文章，查看是否SQL語句正被以批量的「Parameters」語句發送。Status=8代表「Parameters」批處理沒有啓用。

exec sp_addarticle @publication = … @status = 24

或者

select name, status from sysarticles

文章狀態使用如下複製存儲過程按需更新。這應該在全部文章上執行。

EXEC sp_changearticle @publication = N'<pub name>’, @article = N'<article name>’,
@property = ‘status’, @value = ‘parameters’

在訂閱者捕獲Profile的RPC:COMPLETE事件。查看StartTime、EndTime和Duration的差別。語句應該在大約100ms完成。對於單個行更新/插入更長的執行時間，可能代表在訂閱者上的阻塞或者致使高Duration的訂閱表上的用戶自定義觸發器。

查看當設置RPC:COMPLETES和RPC:STARTING時的時間差別。返回分發代理的往返時間說明命令完成和接下來的命令收到。時間差別大於500ms可能代表網絡延時。

檢查從讀取線程完成讀一批命令直到這些命令應用到訂閱者的時間。這兩件事件之間花費較長時間也代表長時間運行的寫入線程。

-- reader thread completed -OUTPUT entry
2009-05-14 01:07:50.795 sp_MSget_repl_commands timestamp value is: 0x0x0000081a00000033000400000000
-- writeer thread commit -OUTPUT entry
2009-05-14 01:13:50.011 Parameterized values for above command(s): {{N’ZZZZZZZZ’, 1}, {N’XXXXXXXX’, 2}, {N’YYYYYYYY’, 3}}

當排查長時間運行的寫入線程時，注意力聚焦在訂閱者上執行UPDATE/INSERT/DELETEs的時間。執行時間能夠從PSSDIAG/Profiler或經過執行DMVs來找到。

Execution time (ms): 3401930
Work time (ms): 3401470
Distribute Repl Cmds Time(ms): 3354520
Fetch time(ms): 3343920
Repldone time(ms): 5520
Write time(ms): 140070
Num Trans: 8 Num Trans/Sec: 0.002352
Num Cmds: 477219 Num Cmds/Sec: 140.297871