原文:Replication的犄角旮旯（六）-- 一个DDL引发的血案(上)（如何近似估算DDL操作进度）
《Replication的犄角旮旯》系列导读
Replication的犄角旮旯（一）--变更订阅端表名的应用场景
Replication的犄角旮旯（二）--寻找订阅端丢失的记录
Replication的犄角旮旯（三）--聊聊@bitmap
Replication的犄角旮旯（四）--关于事务复制的监控
Replication的犄角旮旯（五）--关于复制identity列
Replication的犄角旮旯（六）-- 一个DDL引发的血案(上)（如何近似估算DDL操作进度）
Replication的犄角旮旯（七）-- 一个DDL引发的血案(下)（聊聊logreader的延迟）
Replication的犄角旮旯（八）-- 订阅与发布异构的问题
Replication的犄角旮旯（九）-- sp_setsubscriptionxactseqno，赋予订阅活力的工具
---------------------------------------华丽丽的分割线--------------------------------------------
前言：这是昨天刚刚发生的案例，尽管事件的起因只是一个简单的DDL操作，但影响面和影响时间可以说是大大超出了预期；我们将在描述本案例的前因后果之后，聊聊如何近似估算DDL的操作进度，以及关于logreader延迟的问题；
由于直接找MS开了case，直接引用标准回复格式；
=====================华丽丽的分割线========================
问题描述
=========
对于一张11亿的数据进行PK字段的int到bigint的类型转换,一直没有完成。发现replication延迟仅1小时
问题排查
=========
1.sp_replcounters发现replbeginlsn的值一直没有改变,但是replnextlsn一直在变化
2.sp_replcounters返回未发送的transaction持续上升
发生原因
=========
1. 执行ALTER TABLE修改PK字段从INT到bigint时,由于一直没有完成,这被视为是一个active transaction,这个值代表当前LOG的minLSN, 由于这个transaction一直没有做完,所以这个值一直没有变化
|
Replbeginlsn |
binary(10) |
Log sequence number (LSN) of the current truncation point in the log. |
http://technet.microsoft.com/en-us/library/ms190486(v=SQL.110).aspx
2. 但是根据我们对于log reader的理解,这个beginLSN即使一直没有变化,也不会影响log reader对于日志的读取,因为log reader会直接从replnextlsn开始扫描
3. 由于active transaction一直没有提交,导致日志无法被截断,日志持续自增,目前已经有270GB, 4000个VLF
4. VLF太多通常是会导致log reader读取日志较慢,但是由于目前4000个VLF中只有2500个处于status=2的活动状态,并不是很多,这也不是导致replication延迟的原因
5.select *from fn_dblog(null,null)发现有大量的LOP_MODIFY_COLUMN的日志记录 (处理在LCX_HEAP上),这个应该针对于每一条记录做类型转换时都需要记录的日志.而这个记录还在不断增多.由于这部分日志会有超过11亿条,并且replication不需要发送这些日志(因为这张表已经从article中移除).但是这部分日志还是需要被log reader扫描一遍,然后跳过去,这样的扫描造成了log reader读取日志变慢,从而导致replication的延迟.
解决方案
========
1.持续等待到ALTER TABLE做完,这样log reader跳完了所有的日志以后,replication的延迟会自动追上去
2.手动cancel这个alter table,让他回滚,这样就不会产生新的日志,log reader不需要再扫描那些日志,也会慢慢追上延迟
最后您通过cancel这个alter table的语句,这个问题得以缓解.
下一步方案
========
根据我们以前case的历史背景,和今天的电话沟通,我建议您对于这张表的字段修改还是使用导到新表,然后重命名的方式.因为这样的办法使用的是select into,属于BULK操作,在SIMPLE模式下是不记日志的,所以不会对replication有影响.
=====================华丽丽的分割线========================
案例补充说明：
由于alter table操作并不能直接获取操作的进度（sys.dm_exec_requests中的percent_complete对alter table操作不计算执行进度），经过MS工程师的指点，我们依然可以间接的估算出操作进度；以下通过一个测试案例说明
1、创建一个数据表，填充数据；
test_1表，id列为主键自增列，类型bigint；填充数据51W条，数据大小2G左右；
2、修改id类型（int改为bigint），由于id是主键，所以需要先删除主键约束才能继续alter table。删除主键约束后，手动checkpoint一下，清理一下fn_dblog；
3、执行alter table语句并检查fn_dblog
可以看到大量的修改行的记录，完成alter table后再查一下fn_dblog，总记录数51W多，基本与数据量一致；
4、按照下面的脚本筛选一下，可以看到，alter table操作（对堆表），实际是每行都急了一条modify的日志
SELECT [Current LSN],Operation,Context,[Transaction ID],[Log Record Fixed Length],[Log Record Length], AllocUnitId FROM fn_dblog(NULL,NULL) fnlog WHERE Operation=‘LOP_MODIFY_ROW‘ AND Context=‘LCX_HEAP‘ AND [Transaction ID]=‘0000:00ed4660‘
然后我们在对Current LSN分析，看看跨了几个VLF
形如：00028b3d:0000002f:001e
其中第一段00028b3d表示VLF号，于是将上述结果集中的Current LSN按第一段分组计数，使用下面的脚本即可；
--查询fn_dblog中每个VLF包含的记录数 SELECT LEFT([Current LSN],CHARINDEX(‘:‘,[Current LSN])-1),COUNT(1) FROM fn_dblog(NULL,NULL) fnlog WHERE Operation=‘LOP_MODIFY_ROW‘ AND Context=‘LCX_HEAP‘ AND [Transaction ID]=‘0000:00ed4660‘ GROUP BY LEFT([Current LSN],CHARINDEX(‘:‘,[Current LSN])-1)
可以看到，目前查询到的记录中，平均每个VLF中包含1900左右的记录数
4、先计算出按照平均1900/VLF，需要多少个VLF才能支持写完51W条记录（510000/1900，约为268个VLF）
5、结合DBCC LOGINFO，可以得出当前活动VLF的数量（当alter table执行时，由于未提交或回滚，VLF处于活动状态而不能被截断），在比较预计VLF数和当前活动的VLF，即可知道当前alter table的进度
这里最好加一个限定，fn_dblog查出来的VLF号是16进制的，换成10进制是166717，再去DBCC LOGINFO的结果集查询，增加 fseqno>=166717的条件；
小结：根据fn_dblog中某一段的日志情况（通过Operation=‘LOP_MODIFY_ROW‘ AND Context=‘LCX_HEAP‘ AND [Transaction ID]=‘0000:00ed4660‘确认正在执行的DDL操作，其中[Transaction ID]和Current LSN的起始位置，可以通过dbcc opentran确定），统计出平均VLF中的记录数（由于实际环境中影响日志记录的因素较多，因此需要多看几个VLF来估算DDL操作日志量的平均占比情况），再根据DBCC LOGINFO中当前活动VLF的数量推算出DDL操作的进度；