Troubleshooting Transactional Replication – PART 3


Troubleshooting Transactional Replication - PART 3

“Repl Talk”

--Chris Skorlinski
--Microsoft SQL Server Escalation Services

This is a continuation of “Repl Talk” series on troubleshooting Transactional Replication.  This posting walks through the LogReader as it moves transactions from the published database transaction log to the Distribution database. The walkthrough can be done on a single Microsoft SQL Server 2008 using the AdventureworksLT sample database.  Parts 1 and 2 walk through setting up Transactional Replication. 

http://blogs.msdn.com/chrissk/archive/2010/01/28/troubleshooting-transactional-replication-part-1.aspx
http://blogs.msdn.com/chrissk/archive/2010/01/28/troubleshooting-transactional-replication-part-2.aspx

 

/***** SQL Script to Walkthrough of LogReader Activity

 

Chris Skorlinski

Microsoft SQL Server Escalation Services

 

1) Create Publication and PUSH to Subscriber

 

2) To better demonstrate flow of transactions,

     stop LogReader Agent.

 

Replicated Transaction Information:

        Oldest distributed LSN     : (26:248:32)

        Oldest non-distributed LSN : (0:0:0)  <<<no pending Repl Transactions

 

*****/

 

 

USE [AdventureWorksLT]

GO

 

--Perform a Single Row Update

UPDATE [AdventureWorksLT].[SalesLT].[Product]

  SET ListPrice = ListPrice * 1.1, ModifiedDate = GETDATE()

  Where ProductID = 680

 

 

--Are there any "pending" transactions? 

USE [AdventureWorksLT]

GO

DBCC OPENTRAN

 

 

Transaction information for database 'AdventureWorksLT'.

 

Replicated Transaction Information:

        Oldest distributed LSN     : (26:248:32)

        Oldest non-distributed LSN : (26:262:1)

 

--What is in the Transaction Log?

 

--Use WHERE Description = 'Replicate' to see transactions

--   marked to pickup by the LogReader.

select [Current LSN],[Operation],[Context],[Transaction ID], [Description],

AllocUnitId, AllocUnitName, [Lock Information]

     from ::fn_dblog(null,null)

     --where Description = 'Replicate'

     where [Transaction ID] = '0000:0000070e'

 

Current LSN             Operation                       Context          Transaction ID Description

----------------------- ------------------------------- ---------------- -------------- ------------

0000001a:00000106:0002  LOP_BEGIN_XACT                  LCX_NULL         0000:0000070e  UPDATE 

0000001a:00000106:0003  LOP_DELETE_ROWS                 LCX_MARK_AS_GHOST0000:0000070e  REPLICATE

0000001a:00000106:0004  LOP_INSERT_ROWS                 LCX_CLUSTERED    0000:0000070e  REPLICATE

0000001a:00000106:0005  LOP_COMMIT_XACT                 LCX_NULL         0000:0000070e  REPLICATE 

 

(4 row(s) affected)

 

--(I added the "LOP_BEGIN_XACT" by looking at entire transaction)

--  where [Transaction ID] = '0000:0000070e'

 

 

--How does the LogReader retrieve this transaction?

 

--LogReader make a connection to SQL server and executes command below.

 

sp_replcmds

-- xactid     = Begin Transaction

-- xact_seqno = Commit Transaction

 

article id  partial_command command                                         xactid                 xact_seqno 

----------- --------------- ----------------------------------------------- ---------------------- ----------------------

1           0               0x8C00000003007B00430041004C004C0020005B006400  0x0000001A000001060002 0x0000001A000001060005

  

--How can I see actual TSQL commands

--   the LogReader retrieves from the Transaction Log?

sp_replshowcmds

 

xact_seqno              command

---------------------- ---------------                   

0x0000001A000001060005 {CALL [dbo].[sp_MSupd_SalesLTProduct] (,,,,,1574.6500. ...

 

 

--Run LogReader Agent to move transaction to Distribution Database

sp_replflush  -- clear internal article cache

 

/****

 

Start LogReader from CMD line (as local administrator) to watch activity.

 

Note the Agent performance statistics are automatically included

     during LogReader shutdown when optional -continuous

     is not included as a startup parameter.

    

"C:\Program Files\Microsoft SQL Server\100\COM\logread.exe" -Publisher [CHRISSKACER]
          
-PublisherDB [AdventureWorksLT] -Distributor [CHRISSKACER] -DistributorSecurityMode 1

 

>>>>output<<<<

 

2010-02-02 23:10:53.518 Microsoft SQL Server Log Reader Agent 10.0.2531.0

2010-02-02 23:10:53.518 Copyright (c) 2008 Microsoft Corporation

2010-02-02 23:10:53.519

2010-02-02 23:10:53.519 The timestamps prepended to the output lines
are expressed in terms of UTC time.

2010-02-02 23:10:53.519 User-specified agent parameter values:

                        -Publisher CHRISSKACER

                        -PublisherDB AdventureWorksLT

                        -Distributor CHRISSKACER

                        -DistributorSecurityMode 1

2010-02-02 23:10:53.616 Parameter values obtained from agent profile:

                        -pollinginterval 5000

                        -historyverboselevel 1

                        -logintimeout 15

                        -querytimeout 1800

                        -readbatchsize 500

                        -readbatchsize 500000

2010-02-02 23:10:53.633 Status: 4096, code: 20024, text: 'Initializing'.

2010-02-02 23:10:53.634 The agent is running.

Use Replication Monitor to view the details of this agent session.

2010-02-02 23:10:53.649 Status: 4, code: 22021, text: 'Batch committed. 

Batch consisted of 1 commands, 1 xacts. 
Last xact: 0x0000001a000001060002, '0x0000001a000001060005'.'.

 

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

02-02-2010 18:10:53

 

Execution time (ms): 140

Work time (ms): 15

Distribute Repl Cmds Time(ms): 15

Fetch time(ms): 15

Repldone time(ms): 0

Write time(ms): 0

   Num Trans: 1  Num Trans/Sec: 66.666667

   Num Cmds: 1  Num Cmds/Sec: 66.666667

*******************************************************************************

 

2010-02-02 23:10:53.653 Status: 1, code: 22037, text: 'A total of 1 transaction(

s) with 1 command(s) were delivered.'.

2010-02-02 23:10:53.655 A total of 1 transaction(s) with 1 command(s) were delivered.

 

C:\Program Files\Microsoft SQL Server\100\COM>

 

*****/

 

 

--Are there more pending transactions?

 

DBCC OPENTRAN

 

Replicated Transaction Information:

        Oldest distributed LSN     : (26:262:5) -->>>>0x0000001a000001060005

        Oldest non-distributed LSN : (0:0:0)    -->>>>no "pending" transactions.

 

       

/***** Key TAKEWAYS

 

     Transactions identified by 3-part LSN (Log Sequence Number)

    

     Normal behavior "Oldest distributed LSN" keeps incrementing

    

     "Oldest non-distributed LSN : (0:0:0)" indicates all pending data hasbeen replicated

    

     Log recrods with Description = "replicate" are those read by LogReader

    

*****/

 

Part 4 will show commands to explore the transactions stored in the Distribution Database.  Other posts will cover topics such as Replication Latency.

 


Comments (1)

  1. lanre says:

    Thanks for this post! Really enlightening.

    I don't know if you are aware  of any reason why a distribution agent will keep delivering an initial snapshot continuously in a loop. I've had to upgrade a distributor database from  sql 2000 to sql2008 and I typically just script out the publication, remove the publication via the old distributor and recreate from scratch on the new distributor. The last time I attempted this, the distribution agent delivered the initial snapshot but instead of showing a completed delivery message, it began re-applying the same snapshot again until it failed with a " Could not find stored procedure 'sp_MSins_xxx' " error, even though the SP was created initially.

    I only got this to work by recreating the publication manually but this won't be an option in subsequent upgrades because there are too many articles with filters etc. any hints will be invaluable!

    Thanks

Skip to main content