Replication的犄角旮旯（六）-- 一个DDL引发的血案(上)（如何近似估算DDL操作进度）

《Replication的犄角旮旯》系列导读

---------------------------------------华丽丽的分割线--------------------------------------------

前言：这是昨天刚刚发生的案例，尽管事件的起因只是一个简单的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'

View Code

然后我们在对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)

View Code

可以看到，目前查询到的记录中，平均每个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操作的进度；

posted @ 2014-07-15 10:28 我是大菠萝 Views(1632) Comments(7) Edit 收藏举报

会员力量，点亮园子希望

刷新页面返回顶部

我是大菠萝的博客园

Replication的犄角旮旯（六）-- 一个DDL引发的血案(上)（如何近似估算DDL操作进度）

公告