五、分发代理写者线程延迟

写者线程会调用一些存储过程，将发布方的改变应用到订阅方。这些存储过程依赖于用户表的唯一索引（通常是主键）来定位要更新或删除的记录。写者线程的延迟通常是由于这些存储过程的执行时间过长。

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

ITPub博客

事务复制会话 (五)

最新文章