SQLServerWiki

“The Only Thing That Is Constant Is Change”

Blocking of LogReader History thread can cause latency.

Posted by database-wiki on April 11, 2016

Problem Description:
we’ve encountered a couple of issues where the only indication of a problem was
severe blocking of the Log Reader History Writer thread. In 1 case there were
10million+ MSlogreader_history records. Once this table was truncated latency
issue was resolved.

REPRODUCTION:
==============
To see if blocking of Log Reader History Writer thread can cause Tran Repl latency
I ran the following test.

1) Created a simple 1 table tran repl publication and published to subscriber DB on
the same server.
2) started to replicate changes, and inserted Tracer Token. Data was replicated in
seconds.
3) Ran script below to block writers to [MSlogreader_history]

–place table lock on [MSlogreader_history]
Begin Transaction

UPDATE [distribution].[dbo].[MSlogreader_history] with (Tablock)
SET [delivery_time] = 1
WHERE 1 = 2
GO

–waited 5 minutes to simulate severe blocking
–by the Log Reader thread
Waitfor delay ’00:05:00′

Commit Transaction

4) Made few more changes and inserted more tracer tokens. Within 2 minutes data
changes were no longer being replicated to the subscriber. Tracer Tokens indicate
“pending”

5) When [MSlogreader_history] lock was released data was now replicated.

Log Reader Output provides no indication the READER-THREAD was blocked by the
HISTORY-WRITER thread.

blocked at 10:29:09.302 released at 10:32:51.369

Publisher: {call sp_repldone ( NULL,
0x0000009c00000e930075, 0, 47)}
ublisher: exec sp_replcounters N’TranPub’
OLE DB Publisher ‘CHRISSKGX620′: exec sp_replcounters
N’TranPub’
Status: 4, code: 22021, text: ‘Batch committed. Batch
consisted of 440 commands, 1 xacts. Last xact: 0x0000009c00000c3b0001,
‘0x0000009c00000e930075′.’.

******************** STATISTICS SINCE AGENT STARTED**********************

Execution time (ms): 398223
Work time (ms): 222632
Distribute Repl Cmds Time(ms): 375
Fetch time(ms): 267
Repldone time(ms): 0
Write time(ms): 156
Num Trans: 7 Num Trans/Sec: 0.031442
Num Cmds: 2202 Num Cmds/Sec: 9.890761
***********************************************************************

Publisher: {call sp_replcmds (1, 0, 0, , 222130, 500000)}
Status: 4, code: 20262, text: ‘Delivering replicated
transactions, xact count: 1, command count: 101.’.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
%d bloggers like this: