事務複製會話 (二)

Normal 0 7.8 磅 0 2 false false false EN-US ZH-CN X-NONE二、日誌讀取器讀者執行緒延遲

 

一般故障排除：

向日志讀取器新增“-OUTPUT”引數，來分解讀（Fetch time）和寫（Write time）的會話時間。在下面的示例輸出中，執行該事務，讀者執行緒消耗了55分鐘，而寫者執行緒僅需要3分鐘。這說明，日誌讀取器的讀者執行緒是問題的瓶頸所在。（關於複製日誌讀取器代理，請參考：http://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，請參考：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 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秒執行這個大型事務。

 

解決方法：

如果讀者執行緒延遲是由大量的待完成命令導致的，那麼等待日誌讀取器完成可能是最好的短期解決方案。長期方法包括在非高峰時段複製批資料或者釋出儲存過程執行。

 

（關於在事務複製中釋出儲存過程執行，請參考：

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

GO

DBCC LOGINFO

 

解決方法：

收縮事務日誌來移動多餘的虛擬日誌檔案。合理設定資料庫的“growth”（增長量）值來避免建立大量虛擬日誌檔案。

 （關於如何在SQL Server 2005中使用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。

（關於網路介面物件更多資訊，請檢視：http://msdn.microsoft.com/en-us/library/ms803962.aspx）

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/25175503/viewspace-705413/，如需轉載，請註明出處，否則將追究法律責任。