Share via

事务复制会话 (二)

  • Article

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

 

一般故障排除：

向日志读取器添加“-OUTPUT”参数，来分解读（Fetch time）和写（Write time）的会话时间。在下面的示例输出中，执行该事务，读者线程消耗了55分钟，而写者线程仅需要3分钟。这说明，日志读取器的读者线程是问题的瓶颈所在。（关于复制日志读取器代理，请参考：https://msdn.microsoft.com/zh-cn/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 <-- 读时间为 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，请参考：https://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，请参考：https://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，请参考：https://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) WHERE Description='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-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秒执行这个大型事务。

 

解决方法：

如果读者线程延迟是由大量的待完成命令导致的，那么等待日志读取器完成可能是最好的短期解决方案。长期方法包括在非高峰时段复制批数据或者发布存储过程执行。

 

（关于在事务复制中发布存储过程执行，请参考：

https://msdn.microsoft.com/zh-cn/library/ms152754(SQL.90).aspx）

 

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

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

 

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

 

（关于sp_repldone (Transact-SQL)，请参考：https://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-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).

 

解决方法：

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

 

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

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

 

USE <published DB>

GO

DBCC LOGINFO

 

解决方法：

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

 （关于如何在SQL Server 2005中使用DBCC SHRINKFILE语句收缩事务日志文件，请参考：https://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。

（关于网络接口对象更多信息，请查看：https://msdn.microsoft.com/en-us/library/ms803962.aspx）