事务复制会话--收藏，学习

事务复制会话

当对事务复制性能问题进行故障排除时，我们可以将数据流分为四段同步的会话，测试每段会话的性能，将有助于确认应该从哪里开始瓶颈调查。

1)日志读取器（LogReader）的读者线程通过存储过程sp_replcmds（xp_replcmds的包装）读取事务日志，它会扫描被标记为复制事务的日志，跳过非复制的事务。

2)日志读取器的写者线程使用sp_MSadd_replcmds，将排队事务从读者线程写到分发数据库。

3)分发的读者线程执行sp_MSget_repl_commands，从分发数据库获得未处理的命令并存储到内部队列。

4)分发的写者线程通过以sp_MSupd、sp_MSins、sp_MSdel开头的几个参数化的存储过程，将行的变更应用到订阅方的每个项目，从而将队列中的命令写到订阅服务器。

5)日志读取器和分发服务器也会执行一个“历史”线程，将总结数据写到分发数据库的系统表MSlogreader_history和MSdistribution_history中。

 

 接下来我将分五个部分来讨论事务复制会话:

1.      性能故障排除工具

2.      日志读取器读者线程延迟

3.      日志读取器写者线程延迟

4.       分发代理读者线程延迟

5.       分发代理写者线程延迟

  

一、性能故障排除工具

 SQLServer事件探查器（SQL Profiler）：查看事务复制会话的信息有多种方法。与所有连接到SQLServer的应用程序一样，复制组件执行的每条命令都可以被事件探查器跟踪抓取。跟踪信息可以被存储或查询，从而找到运行时间较长的语句。

   跟踪信息中的“应用名称”举例：

• REPLICATION MONITOR —— Management Studio的用户界面
• REPL-LOGREADER-#-DatabaseName-#——日志读取器代理向分发表记录变更的写者线程
• ServerName\Instance-DatabaseName-PubName-Subscriber——来自分发代理的读者线程，用于找出哪些命令/事务要复制到订阅方
• REPLCATION
  LOGREAD HISTORY——日志读取器代理用来记录历史的写者线程
• REPLICATION
  DISTRIBUTION HISTORY——分发代理用于记录历史的写者线程

  复制存储过程调用举例：

            ·    分发活动

• SP_MSGET_REPL_COMMANDS
• SP_MSHELP_DISTRIBUTION_AGENTID
• SP_MSGET_SUBSCRIPTION_GUID

            ·    日志读取器活动

• 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}

           ·    订阅服务器活动

• SP_MSins%
• SP_MSupd%
• SP_MSdel%

 

活动监视器（Activity Monitor）：SQL Server ManagementStudio活动监视器、SQL 2005的性能仪表盘（PerformanceDashboard）、SQL 2008的性能数据仓库（PerformanceDatabase Warehouse）、以及系统存储过程，可以帮助查找阻塞、磁盘瓶颈和导致高IO和高CPU的语句。为了识别复制组件，我们可以查找日志读取器或分发代理作业连接到SQLServer的程序名。查找复制作业的列表，可运行下面的语句：

 SELECT name,description, enabled from MSDB..sysjobs

WHERE category_id>10and category_id<20

 

跟踪令牌（Tracer Tokens）：使用复制监视器中的跟踪令牌功能，可以得到复制性能的概览。该功能提供了“发布服务器到分发服务器”以及“分发服务器到订阅服务器”的等待时间值。要使用该功能，开启复制监视器。在My Publishers表中，选择想要测试的发布。在右边的面板，选择Tracer Tokens标签，并点击“Insert Tracer Token”按钮。下面将会出现一个订阅方列表，可获得“发布服务器到分发服务器”和“分发服务器到订阅服务器”的值。

 该方法仅对实时复制有用。如果拓扑是晚3天的，那将不会看到跟踪令牌按时到订阅方，所以，你只能看到日志读取器在时间上是否落后。这其实还是很有用的信息，尤其是在当订阅方只晚了五分钟，你可以看到令牌全程传递的情况。

 如果看到“发布服务器到分发服务器”的时间很长，就要集中于日志读取器性能的问题排除。如果日志读取器性能很好，但“分发服务器到订阅服务器”的值很大，那么说明，事务从被发布数据库的事务日志到分发数据库的过程很快，但是从分发数据库到订阅数据库很慢。分发代理应当作为瓶颈调查的关键。

 下面的链接提供了估计延迟时间的示例代码：

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

·    http://blogs.mssqltips.com/blogs/chadboyd/archive/2007/10/24/monitoring-replication-latency-automatically-using-tracer-tokens-sp-replchecklatency-allpubs.aspx

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

性能监视器（Performance Monitor）：我们也可以使用Windows性能监视器来跟踪复制日志读取器的“LogReader:Delivery Latency” 计数器或者复制分发的“Dist:Delivery Latency”计数器。不过，Windows性能监视器的复制计数器值仅在日志读取器或分发代理完成一个过程阶段并记录了性能状态之后才会更新。所以即使有一个包含上百万行的事务在处理，计数器的值也将显示为0 commands/sec及0 transactions/sec 

二、日志读取器读者线程延迟

 一般故障排除：

向日志读取器添加“-OUTPUT”参数，来分解读（Fetch time）和写（Write time）的会话时间。在下面的示例输出中，执行该事务，读者线程消耗了55分钟，而写者线程仅需要3分钟。这说明，日志读取器的读者线程是问题的瓶颈所在。（关于复制日志读取器代理，请参考：http://msdn.microsoft.com/zh-cn/library/ms146878.aspx）

 

***************STATISTICSSINCE AGENT STARTED ******************
Execution time (ms): 3401930
Work time (ms): 3401470
Distribute Repl Cmds Time(ms): 3354520
Fetch time(ms): 3343920   <-- 读时间为 55 分钟
Repldone time(ms): 5520
Write time(ms): 140070    <-- 写时间为3分钟
   Num Trans: 8  Num Trans/Sec: 0.002352
   Num Cmds: 477219  Num Cmds/Sec: 140.297871
****************************************************************

 

从以下SQL Server版本开始，日志读取器代理统计将每五分钟显示一次并写入分发数据库的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命令可以看到事务日志的大小。

 DBCC SQLPERF(LOGSPACE)

 日志读取器的读者线程执行sp_replcmds从事务日志读取命令。下面的存储过程可以在SSMS中执行，用来跟踪下一个未处理复制事务所需要的时间。我们可以得到信息诸如，这些命令需要执行多久？返回了多少条命令？扫描一个包含上百万行数据更改事务所对应的大型事务日志，可能要花费二十多分钟。这个查询的执行时间大致与日志读取器复制一个相同事务的开启时间相同。

 

显示第一个未处理的事务元数据，比如publication_id、article id、xactid以及command_type。从中去判断这个命令是一般数据库操作的一部分还是预期之外的大批的命令。

（关于sp_replcmds [ @maxtrans = ] maxtrans，请参考：http://msdn.microsoft.com/zh-cn/library/ms186983.aspx）

 

示例:

--返回下一个待完成事务的所有命令

sp_replcmds @maxtrans = 1

GO

 

--返回下面500个事务的所有命令

sp_replcmds @maxtrans = 500

GO

sp_replflush

GO

 

显示第一个事务的元数据以及待复制的命令文本。命令类型=1073741871表示待完成的跟踪令牌

（关于sp_replshowcmds [ @maxtrans = ] maxtrans，请参考：http://msdn.microsoft.com/zh-cn/library/ms175114.aspx）

 

示例:

--返回从下一个待完成事务开始的所有命令及命令文本

sp_replshowcmds@maxtrans = 1

GO

 

--返回之后500个事务的所有命令及命令文本

sp_replshowcmds @maxtrans = 500

GO

sp_replflush

GO

 

另一个查看一批待完成事务/命令的总结信息方法为，查询sys.dm_repl_traninfo视图。这将显示最后一次被sp_replcmds或者sp_replshowcmds读取的日志中复制事务的总结信息，包括“cmds_in_tran”。值比较大可能说明有一个大型事务正在被复制。

（关于sys.dm_repl_traninfo，请参考：http://msdn.microsoft.com/zh-cn/library/ms180036.aspx）

 

sp_replcmds @maxtrans = 500  --获得500个待完成状态的事务

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

 

下面的这个命令可以用来确定复制事务与非复制事务的数量。一个包含大量非复制事务的事务日志将会导致延迟，因为日志读取器也会扫描非复制事务。这个事务可能是数据库维护事务，比如在线索引重建或者不被复制的表数据更改。根据不同的IO子系统，一个25GB的事务日志可能要花费15分钟进行扫描。

 

Use <published database>

GO

--日志中的所有记录

SELECT count(*) FROM::fn_dblog(NULL, NULL)

GO

--标记为复制的记录

SELECT count(*) FROM::fn_dblog(NULL, NULL) WHEREDescription='REPLICATE'

GO

 

如果在执行sp_replcmds时获得了大型事务，那么在SQL Server事件探查器跟踪（Profiler trace）数据中也将看到那个事件的长时间运行。使用下面的命令查询抓取的事件探查器跟踪的结果。

 

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-2115:00:06.010    2008-10-21 15:00:06.010    exec sp_replcmds 500,0,-1,0x,5000,0,500000
       393         2008-10-2115:00:11.010    2008-10-21 15:00:11.010    exec sp_replcmds 500,0,-1,0x,5000,0,500000
       397         2008-10-2115:00:16.010    2008-10-21 15:00:16.010    exec sp_replcmds 500,0,-1,0x,5000,0,500000
        66302488    2008-10-2115:00:21.010    2008-10-21 15:01:27.290    exec sp_replcmds 500,0,-1,0x,5000,0,500000
       413         2008-10-2115: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/zh-cn/library/ms152754(SQL.90).aspx）

 

另一个方法是通过配置日志读取器，将一个大事务分解到多个小批。通过小批量数据来提交大事务，可以减少总体的日志读取开销。不过，当用多个平行流分发数据到订阅方时，性能改进会更显著。

（关于复制日志读取器代理，请参考：http://msdn.microsoft.com/zh-cn/library/ms146878.aspx）

 

基于读取待完成事务并将其传递到订阅方的时间估计，可以将所有事务标记为“replicated”，然后使用新快照或通过备份/还原重新初始化订阅方，这样也是一种方法。但是这个方法应该当产生新复制快照并传递到订阅方的时间比等待复制的待完成命令完成来得短的时候才使用。

 

（关于sp_repldone (Transact-SQL)，请参考：http://msdn.microsoft.com/zh-cn/library/ms173775.aspx）

 

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

 

可能原因：大量的非复制事务

这种情况会比较难确定。最好用户可以知道哪个条目正在被复制以及最近是否执行了批处理。事件探查器跟踪中的BINARY列显示了被sp_replcmds执行的行数。有多个执行但行数很少，通常说明日志读取器正花时间跳过非复制事务，比如一个正在执行索引重建的较大表。

 

下面日志读取器日志的输出结果表明，有很多行被读取但只有很少行在被复制：

 

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

 

解决方法：

当存在大量非复制表的事务时，这种情况是难以避免的。如���问题是由索引维护日志记录导致，可以考虑执行离线索引重建。另外一个方法是，停止然后启动在线索引重建，创建更小批的索引更新事务。

 

可能原因：大量的虚拟日志文件（Virtual Log Files，VLFs）

大量的虚拟日志文件可能会导致日志读取器花更得地时间在读取上。要确定虚拟日志文件的数量，执行下面的命令并查看返回行的数量。超过十万行可能就会导致日志读取器读者线程有性能问题。

 

USE <publishedDB>

GO

DBCC LOGINFO

 

解决方法：

收缩事务日志来移动多余的虚拟日志文件。合理设置数据库的“growth”（增长量）值来避免创建大量虚拟日志文件。

 （关于如何在SQL Server2005中使用DBCC SHRINKFILE语句收缩事务日志文件，请参考：http://support.microsoft.com/default.aspx?scid=kb;ZH-CN;907511）

 

可能原因：读操作IO慢

磁盘系统慢可能会导致较长的读取时间。Windows性能监视器的Avg Disk Sec/Read计数器是对磁盘读性能的一个较好的整体估计。

解决方法：

读时间>15ms（.0015）可能表示了一个IO读瓶颈，应该让存储系统厂商进行查看。

可能原因：网络IO慢

对于使用请求（PULL）日志读取器的远程分发者，logread.exe在分发服务器上执行却从发布服务器的事务日志中请求行。预期之外的网络IO将会导致读者线程的延迟。

 解决方法：

同时在发布服务器和分发服务器上使用Windows性能监视器，检查活动网卡（Network Interface Card, NIC）的网络接口“Output Queue Length”计数器，该计数器值应一直小于2。

三、日志读取器写者线程延迟

 

可能原因：阻塞

日志读取器代理-OUTPUT日志中“write time（ms）”的值很高，表明向分发数据库写命令时有瓶颈问题。阻塞可能是由其他SQL复制代理造成的，比如分发清除代理。我们使用SQL Server内部工具，比如SSMS活动监视器、性能仪表盘（Performance Dashboard）、性能数据仓库（Performance Database Warehouse）或者sp_who存储过程，来查看日志读取器写者线程的阻塞情况。

 

对于SQL2005性能仪表盘，它提供了一个较高层次查看分发者性能的视角。阻塞、长时间的查询、高IO等待时间都被显示为图形格式。对于SQL 2008，这些报告被包含在性能数据仓库中。

（关于SQL Server 2005 性能仪表盘报告，请参考：http://www.microsoft.com/downloads/details.aspx?familyid=1d3a4a0d-7e0c-4730-8204-e419218c1efc&displaylang=en）

 

 解决方法：

如果阻塞源（head blocker）是分发清理，请考虑停止这个代理，允许数据先被复制，然后在非高峰时段重新启动清理。阻塞也可能说明IO比预期花费的时间要长。请查看下面的“高IO”来获得更多故障排除步骤。

 

可能原因：高IO

在分发服务器上收集事件探查器跟踪，查看sp_Msadd_replcmds执行的时间长度和CPU值。高IO可能表明有一个比较糟糕的查询计划。使用所抓取的事件探查器跟踪，利用下面的语句来读取已完成事件的CPU和持续时间信息。

 

SELECT duration, starttime, endtime, textdata

FROM ::fn_trace_gettable('C:\DISTRIBUTOR_sp_trace.trc', DEFAULT)

WHERE TEXTDATA LIKE '%SP_MSadd_replcmds%' AND EVENTCLASS=10

 

如何持续时间是CPU时间的十倍，说明资源出现竞争。我们需要在分发服务器上查看日志读取器代理的阻塞情况。

 

SQL 2005和SQL 2008系统的DMV也可以用来获得日志读取器写者线程的持续时间和CPU值。持续时间和CPU值小但逻辑读高，说明可能是一个由数据表统计造成的低效查询计划。下面的命令可以获取查询计划和执行统计。

 

--日志读取器写线程sp_MSadd_replcmds的dm_exec_query_stats

--以toptotal_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性能监视器的Avg Disk sec/write计数器是对磁盘写性能的一个较好估计。

 

解决方法：

写时间>20ms（.0020）说明有IO写瓶颈，应寻求系统存储厂商进行查看。

 

可能原因：网络IO

与上面的情景一样，你可能需要确定网络接口的队列长度。

四、分发代理读者线程延迟

与日志读取器一样，分发代理也是有两个会话同步进行。从分发服务器到订阅服务器移动行的延迟在两种会话中都可能会发生。读者线程会话负责查询分发数据库，从而得到要应用到订阅方的事务列表。它首先查询订阅数据库的元数据表，找到最后一次成功复制的事务。然后，读者线程执行sp_Msget_repl_commands开始从分发数据库读数据行并将这些行迁移至内存中的队列。当行进入队列，分发代理写者线程会话开始将这些行写到订阅服务器。和日志读取器类似，添加分发代理 –OUTPUT参数，会得到对分发代理性能的一个很好的概览。另外，最新版本的SQL Server会在分发代理历史表Msdistribution_history中自动记录这些信息。

  

可能的原因：大批量的事务

延迟问题通常在一系列事务尝试向订阅方移动大批的命令时产生。下面的查询显示了在分发数据库中命令的所有行数以及索引统计数据的信息。

 

--ROW COUNTS

--寻找大的行数值（>1百万），从而说明清除过程没有在运行

--或者有大的待完成事务

SELECT name, rowcnt, STATS_DATE (id, indid) as 'Last UpdateStats'

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 bypublisher_database_id, sum(CommandCount) Desc

ORDER BY publisher_database_id, Month, Day, Hour

 

在下面的输出示例中，由于发布表的大量更新，一大批的事务正在被复制，导致分发代理变慢。

 

publisher_database_idYear       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性能。如果问题持续发生，请考虑发布存储过程执行而不是其结果行。

（关于在事务复制中发布存储过程执行，请参考：http://msdn.microsoft.com/zh-cn/library/ms152754(SQL.90).aspx）

 

 故障排除读者线程：当从分发数据库中获取行时，读者线程中的分发代理可能出现延迟。建议先查看代理历史日志或在-OUTPUT结果中查看每五分钟产生的代理统计信息。

 

****************STATISTICS SINCE AGENT STARTED ******************

03-22-200909:55:19

 

Total Run Time(ms) : 59189906       Total Work Time  : 492741

Total NumTrans     : 5     NumTrans/Sec    : 0.01

Total NumCmds      : 5     NumCmds/Sec     : 0.01

Total IdleTime     : 58660470

 

Writer ThreadStats

  TotalNumber of Retries   : 0

  TimeSpent on Exec        : 0

  TimeSpent on Commits (ms): 16    Commits/Sec         : 0.05

  Time toApply Cmds (ms)   : 0      Cmds/Sec           : 0.00

  Time CmdQueue Empty (ms) : 528717         Empty QWaits > 10ms: 5

  TotalTime Request Blk(ms): 59189187

  P2P WorkTime (ms)        : 0     P2P Cmds Skipped    : 0

 

Reader ThreadStats

  Calls toRetrieve Cmds    : 11738

  Time toRetrieve Cmds (ms): 492741        Cmds/Sec            : 0.01

  Time CmdQueue Full (ms)  : 0      Full Q Waits > 10ms : 0

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

 

以上信息是取自分发代理日志的-OUTPUT输出，可以发现在代理停止工作之前，100%的时间都花在从分发数据库读取行的过程。

 

代理日志同时记录了事件完成的时间。在下面的例子中，从分发代理在订阅方查询待复制的开始事务，到它从分发数据库获取一个批的事务之间，分发代理查询花掉了4分钟的时间。这个延迟是由读者线程等待分发数据库返回命令导致的。

 

--分发代理-OUTPUT输出显示的读者线程延迟示例

--元数据订阅读操作完成

2009-05-1601:26:49.229 OLE DB Distributor 'SQL380': {call sp_MSget_subscription_guid(11)}

--4分钟后命令复制的读操作完成

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

--读者线程等待分发数据库返回命令

 

要测试读的执行时间，我们可以运行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

 

1. 从同一个日志中得到Agent_ID

 

1. 在分发数据库上执行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 STATISTICSPROFILE ON

SET STATISTICS IOON

SET STATISTICSTIME ON

 

sp_MSget_repl_commands @agent_id=11, @last_xact_seqno=0x0000081a00000045000400000000

 

SET STATISTICSPROFILE OFF

SET STATISTICS IOOFF

SET STATISTICSTIME OFF

 

在SQL2005/2008中，我们还可以从DMV中得到缓存的执行计划。

 

--dm_exec_query_statsfor sp_MSget_repl_commands

-- by toptotal_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

   WITHFULLSCAN

 

UPDATE STATISTICS MSrepl_commands

   WITHFULLSCAN

 

解决方法：

使用SQL内部工具，确定分发代理读者线程在分发数据库上没有被阻塞。

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

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

 

sp_MSIns_articlename

sp_MSUpd_articlename

sp_MSDel_articlename

 

在下面的示例输出中，分发代理延迟在其写者线程中发生：

 

****************STATISTICS SINCE AGENT STARTED ******************

Total Run Time(ms) : 18828  Total Work Time  : 14110

Total NumTrans     : 52  Num Trans/Sec    : 3.69

Total NumCmds      : 52  NumCmds/Sec     : 3.69

Writer ThreadStats

  TimeSpent on Exec        : 12063

  TimeSpent on Commits (ms): 422  Commits/Sec     : 0.14

  Timeto Apply Cmds (ms)   : 14110 Cmds/Sec       : 3.69   <-- 写线程

  Time CmdQueue Empty (ms) : 671  Empty Q Waits > 10ms: 2

  TotalTime Request Blk(ms): 671

Reader Thread Stats

  Calls toRetrieve Cmds    : 2

  Timeto Retrieve Cmds (ms): 92  Cmds/Sec      :565.22   <-- 读线程

  Time CmdQueue Full (ms)  : 5486  Full Q Waits > 10ms : 3

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

 

在该输出中，92ms完成了读操作，速度565 cmds/sec；写操作用了14000ms（14秒），速度仅为3.69 cmds/sec。这个例子表明，写操作比读操作慢。

 

可能原因：用来将事务应用到订阅方的INS/UPD/DEL（插入/更新/删除）存储过程的运行时间长。

 

--dm_exec_query_statsfor 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<table name>%'

  ORDER BY qs.total_worker_time DESC

 Go

 

如果存储过程已经从缓存中被清除或者SQL Server已经重启，问题过程中订阅端的事件探查器跟踪可以提供执行的总结数据。可以用SQL Nexus或者fn_ReadTrace加载跟踪文件，然后用下面语句得到分发代理的存储过程的一个总结信息。

 

-- 衡量所有spids 的性能

select hashid, count(*) as Num, sum(duration) assumdur, sum(cpu) assumcpu, 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  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

 

可能原因：用户定义的触发器（User Defined Triggers）

日志读取器代理-OUTPUT输出日志中“write time（ms）”的值很高，揭示了到分发数据库写命令的瓶颈。一个可能的原因是由其他复制代理导致的用于调查阻塞的用户自定义触发器。

 

可能原因：没有将SQL语句以“参数”的形式复制

获得创建发布的脚本，并检查所有项目（articles），查看所有的项目是否有SQL语句被作为批的 “参数”来发送。状态status=8说明“参数”批没有被启用。

 

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

或

  select name, status from sysarticles

 

项目的状态可以使用下面的复制存储过程来更新。需在所有的项目上执行。

EXECsp_changearticle @publication = N'<pub name>', @article = N'<articlename>',

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

 

在订阅服务器上抓取事件探查器的事件RPC:COMPLETE。查看StartTime和EndTime的差距以及/或者持续时间。语句通常应在100ms左右完成。对于使用了更长执行时间的单行更新/插入的操作，说明订阅方可能有阻塞，或者订阅方数据表上的用户自定义触发器导致了较长的持续时间。

 

查看RPC:COMPLETES的时间以及下一个PRC:STARTING的时间差距。这是表明命令已完成且下条命令已获得的，然后回到分发代理的一个“往返”时间。时间差大于500ms说明可能有网络延迟。

 

同时，检查从读者线程读完一批命令到这些命令被应用到订阅服务器之间的时间。这两个事件之间时间长也表示了写者线程花费的时间长。

 

--读者线程完成的-OUTPUT结果

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

--写着线程完成的-OUTPUT结果

2009-05-14 01:13:50.011Parameterized 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