事务复制会话

原文地址：

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