事務複製會話 (五)

五、分發代理寫者執行緒延遲

寫者執行緒會呼叫一些儲存過程，將釋出方的改變應用到訂閱方。這些儲存過程依賴於使用者表的唯一索引（通常是主鍵）來定位要更新或刪除的記錄。寫者執行緒的延遲通常是由於這些儲存過程的執行時間過長。

sp_MSIns_articlename

sp_MSUpd_articlename

sp_MSDel_articlename

在下面的示例輸出中，分發代理延遲在其寫者執行緒中發生：

********************* 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

***************************************************************************************

在該輸出中，92ms完成了讀操作，速度565 cmds/sec；寫操作用了14000ms（14秒），速度僅為3.69 cmds/sec。這個例子表明，寫操作比讀操作慢。

可能原因：用來將事務應用到訂閱方的INS/UPD/DEL（插入/更新/刪除）儲存過程的執行時間長。

--dm_exec_query_stats for sp_MSupd (Subscriber Updates)

-- 以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

%'

ORDER BY qs.total_worker_time DESC

Go

如果儲存過程已經從快取中被清除或者SQL Server已經重啟，問題過程中訂閱端的事件探查器跟蹤可以提供執行的總結資料。可以用SQL Nexus或者fn_ReadTrace載入跟蹤檔案，然後用下面語句得到分發代理的儲存過程的一個總結資訊。

-- 衡量所有spids 的效能

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) asavgwrites

INTO ReadTrace.topCPUBatch

FROM ReadTrace.tblBatches

group by hashid

order by sumcpu desc

GO

-- 得到最消耗CPU的批語句

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	Avqcpu	Avqreads	Avgwrites	normText
--------	---	-------	-------	--------	--------	------	------	-------	-------	-------------
5684440255897011116	69	966058	389	4071	0	14000	5	39	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

可能原因：使用者定義的觸發器（User Defined Triggers）

日誌讀取器代理-OUTPUT輸出日誌中“write time（ms）”的值很高，揭示了到分發資料庫寫命令的瓶頸。一個可能的原因是由其他複製代理導致的用於調查阻塞的使用者自定義觸發器。

可能原因：沒有將SQL語句以“引數”的形式複製

獲得建立釋出的指令碼，並檢查所有專案（articles），檢視所有的專案是否有SQL語句被作為批的 “引數”來傳送。狀態status=8說明“引數”批沒有被啟用。

exec sp_addarticle @publication = ... @status = 24

或

select name, status from sysarticles

專案的狀態可以使用下面的複製儲存過程來更新。需在所有的專案上執行。

EXEC sp_changearticle @publication = N'', @article = N'

',

@property = 'status', @value = 'parameters'

在訂閱伺服器上抓取事件探查器的事件RPC:COMPLETE。檢視StartTime和EndTime的差距以及/或者持續時間。語句通常應在100ms左右完成。對於使用了更長執行時間的單行更新/插入的操作，說明訂閱方可能有阻塞，或者訂閱方資料表上的使用者自定義觸發器導致了較長的持續時間。

檢視RPC:COMPLETES的時間以及下一個PRC:STARTING的時間差距。這是表明命令已完成且下條命令已獲得的，然後回到分發代理的一個“往返”時間。時間差大於500ms說明可能有網路延遲。

同時，檢查從讀者執行緒讀完一批命令到這些命令被應用到訂閱伺服器之間的時間。這兩個事件之間時間長也表示了寫者執行緒花費的時間長。

--讀者執行緒完成的-OUTPUT結果

2009-05-14 01:07:50.795 sp_MSget_repl_commands timestamp value is: 0x0x0000081a00000033000400000000

--寫著執行緒完成的-OUTPUT結果

2009-05-14 01:13:50.011 Parameterized values for above command(s): {{N'ZZZZZZZZ', 1}, {N'XXXXXXXX', 2}, {N'YYYYYYYY', 3}}

最後，當對長時間的寫程式進行故障排除時，注意訂閱方執行UPDATE/INSERT/DELETE操作的時間，執行時間既可以從PSSDIAG/事件探查器追蹤或者通過執行DMV得到。

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