《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操作的進度；