事务复制会话 (四)
四、分发代理读者线程延迟
与日志读取器一样，分发代理也是有两个会话同步进行。从分发服务器到订阅服务器移动行的延迟在两种会话中都可能会发生。读者线程会话负责查询分发数据库，从而得到要应用到订阅方的事务列表。它首先查询订阅数据库的元数据表，找到最后一次成功复制的事务。然后，读者线程执行sp_Msget_repl_commands开始从分发数据库读数据行并将这些行迁移至内存中的队列。当行进入队列，分发代理写者线程会话开始将这些行写到订阅服务器。和日志读取器类似，添加分发代理 –OUTPUT参数，会得到对分发代理性能的一个很好的概览。另外，最新版本的SQL Server会在分发代理历史表Msdistribution_history中自动记录这些信息。
可能的原因：大批量的事务
延迟问题通常在一系列事务尝试向订阅方移动大批的命令时产生。下面的查询显示了在分发数据库中命令的所有行数以及索引统计数据的信息。
--ROW COUNTS
--寻找大的行数值（>1百万），从而说明清除过程没有在运行
--或者有大的待完成事务
SELECT name, rowcnt, STATS_DATE (id, indid) as 'Last Update Stats'
FROM distribution.dbo.sysindexes
WHERE name IN('ucMSrepl_transactions', 'ucMSrepl_commands')
行数是预期的值，还是包含了上百万行？行数多（>1百万）可能说明一个大的事务正在运行或者清除作业没有在运行。
在进行延迟的性能故障排除时，按天计算命令的数量来查看未处理的命令可能会发现有一些有帮助的模式。下面的语句可以查询到存储在分发数据库中命令的拆分信息。
--检查临时表中与那些事务数目相关的时间信息
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
--显示每小时以及每天的命令数
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
解决方法：
分发数据库上的分发代理读者线程对大批事务有很大的IO需求。快速的磁盘以及将事务日志和数据库文件分别存放在不同的磁盘上会帮助改进IO性能。如果问题持续发生，请考虑发布存储过程执行而不是其结果行。
（关于在事务复制中发布存储过程执行，请参考：https://msdn.microsoft.com/zh-cn/library/ms152754(SQL.90).aspx）
故障排除读者线程： 当从分发数据库中获取行时，读者线程中的分发代理可能出现延迟。建议先查看代理历史日志或在-OUTPUT结果中查看每五分钟产生的代理统计信息。
**************** 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%的时间都花在从分发数据库读取行的过程。
代理日志同时记录了事件完成的时间。在下面的例子中，从分发代理在订阅方查询待复制的开始事务，到它从分发数据库获取一个批的事务之间，分发代理查询花掉了4分钟的时间。这个延迟是由读者线程等待分发数据库返回命令导致的。
--分发代理-OUTPUT输出显示的读者线程延迟示例
--元数据订阅读操作完成
2009-05-16 01:26:49.229 OLE DB Distributor 'SQL380': {call sp_MSget_subscription_guid(11)}
--4分钟后命令复制的读操作完成
2009-05-16 01:29:31.401 sp_MSget_repl_commands timestamp value is: 0x0x0000081a00000045000400000000
--读者线程等待分发数据库返回命令
要测试读的执行时间，我们可以运行sp_Msget_repl_commands，从而查找阻塞、表扫描、超时等信息。
- 从-OUTPUT输出得到长时间运行的sp_Msget_repl_commands的LSN
2009-05-16 01:29:31.401 sp_MSget_repl_commands timestamp value is: 0x0x0000081a00000045000400000000
- 从同一个日志中得到Agent_ID
- 在分发数据库上执行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>
--获得上一个成功执行的事务
--每个发布有多个行说明有并行的分发流。
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 2005/2008中，我们还可以从DMV中得到缓存的执行计划。
--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
可能原因：表统计信息
当读者线程运行时间长并包含很多小批事务时，可能说明复制系统表需要更新统计信息。如果分发数据库的AutoUpdateStatistics被禁用了，表统计信息就可能会过期。
-- 查看复制表的表统计信息，尤其是'Updated'（被更新）的日期
DBCC SHOW_STATISTICS(MSrepl_commands,ucMSrepl_commands)
DBCC SHOW_STATISTICS(MSrepl_transactions,ucMSrepl_transactions)
-- 获得分发数据库的设置
-- 查找IsAutoUpdateStatistics
sp_helpdb distribution
--或(返回 1表示IsAutoUpdateStatistics为“是”)
select DATABASEPROPERTYEX('distribution','IsAutoUpdateStatistics')
解决方法：
--更新复制表的统计信息
UPDATE STATISTICS MSrepl_transactions
WITH FULLSCAN
UPDATE STATISTICS MSrepl_commands
WITH FULLSCAN
解决方法：
使用SQL内部工具，确定分发代理读者线程在分发数据库上没有被阻塞。