SQL2016 Replication - Distribution Agent Falling Behind

Kathy Gibson 96 Reputation points
2020-09-17T18:52:01.243+00:00

I have a SQL2016 Std publisher replicating to a SQL2016 Std distributor/subscriber (test environment). It doesn't seem like the replication stream has all that many commands but it keeps falling behind.

I'm using a modified agent profile where I increased the Message Interval parameter to 120 (-Subscriber [XXREPV02] -SubscriberDB [smdb_test] -Publisher [XXXXTSTV02] -Distributor [XXREPV02] -DistributorSecurityMode 1 -Publication [sm_all_tables] -PublisherDB [smdb] -Continuous -HistoryVerboseLevel 3 -SkipErrors 2601:2627:20598 -OutputVerboseLevel 3 -Output "E:\Temp\DAgentOutput.txt" -MessageInterval 120

I have almost 4 million undistributed commands at this point. I've started outputting diagnostics to file, but I need some help interpreting them. If anyone could assist that would be very helpful.

here's the log output.

2020-09-17 17:53:43.560 Microsoft SQL Server Distribution Agent 13.0.5026.0
2020-09-17 17:53:43.607 Copyright (c) 2016 Microsoft Corporation
2020-09-17 17:53:43.623 Microsoft SQL Server Replication Agent: distrib
2020-09-17 17:53:43.638
2020-09-17 17:53:43.654 The timestamps prepended to the output lines are expressed in terms of UTC time.
2020-09-17 17:53:43.669 User-specified agent parameter values:
-Subscriber DBREPV02
-SubscriberDB smdb_test
-Publisher SMDBTSTV02
-Distributor DBREPV02
-DistributorSecurityMode 1
-Publication sm_all_tables
-PublisherDB smdb
-Continuous
-HistoryVerboseLevel 3
-SkipErrors 2601:2627:20598
-OutputVerboseLevel 3
-Output E:\Temp\DAgentOutput.txt
-MessageInterval 120
-XJOBID 0x3242894DDD32BF4FB4E27325C4A0C9CD
-XJOBNAME SMDBTSTV02-smdb-sm_all_tables-DBREPV02-28
-XSTEPID 2
-XSUBSYSTEM Distribution
-XSERVER DBREPV02
-XCMDLINE 0
-XCancelEventHandle 0000000000001B84
-XParentProcessHandle 0000000000002738
2020-09-17 17:53:43.841 Startup Delay: 2382 (msecs)
2020-09-17 17:53:46.253 Connecting to Distributor 'DBREPV02'
2020-09-17 17:53:46.253 Connecting to OLE DB Distributor at datasource: 'DBREPV02', location: '', catalog: '', providerstring: '' using provider 'SQLNCLI11'
2020-09-17 17:53:46.300 OLE DB Distributor: DBREPV02
DBMS: Microsoft SQL Server
Version: 13.00.5026
catalog name:
user name: dbo
API conformance: 0
SQL conformance: 0
transaction capable: 1
read only: F
identifier quote char: "
non_nullable_columns: 0
owner usage: 15
max table name len: 128
max column name len: 128
need long data len:
max columns in table: 1000
max columns in index: 16
max char literal len: 131072
max statement len: 131072
max row size: 131072
2020-09-17 17:53:46.316 OLE DB Distributor 'DBREPV02': exec sp_helpdistpublisher N'SMDBTSTV02'
2020-09-17 17:53:46.332 OLE DB Distributor 'DBREPV02': select @@SERVERNAME
2020-09-17 17:53:46.347 OLE DB Distributor: DBREPV02
DBMS: Microsoft SQL Server
Version: 13.00.5026
catalog name: distribution
user name: dbo
API conformance: 0
SQL conformance: 0
transaction capable: 1
read only: F
identifier quote char: "
non_nullable_columns: 0
owner usage: 15
max table name len: 128
max column name len: 128
need long data len:
max columns in table: 1000
max columns in index: 16
max char literal len: 131072
max statement len: 131072
max row size: 131072
2020-09-17 17:53:46.363 OLE DB Distributor 'DBREPV02': execute sp_server_info 18

2020-09-17 17:53:46.378 ANSI codepage: 1
OLE DB Distributor 'DBREPV02': select datasource, srvid from master..sysservers where upper(srvname) = upper(N'SMDBTSTV02')
2020-09-17 17:53:46.394 OLE DB Distributor 'DBREPV02': select datasource, srvid from master..sysservers where upper(srvname) = upper(N'DBREPV02')
2020-09-17 17:53:46.410 Subscriber security mode: 0, login name: snapple.
2020-09-17 17:53:46.427 OLE DB Distributor 'DBREPV02': SELECT count(*) FROM msdb.sys.columns WHERE object_id = object_id(N'msdb..MSagentparameterlist') and name = N'is_reloadable'
2020-09-17 17:53:46.442 OLE DB Distributor 'DBREPV02': exec sp_MShelp_distribution_agentid 4, N'smdb', N'sm_all_tables', 0, N'smdb_test', 0
2020-09-17 17:53:46.458 OLE DB Distributor 'DBREPV02': execute sp_MShelp_profile 28, 3, N'Default agent profile'
2020-09-17 17:53:46.474 Parameter values obtained from agent profile:
-bcpbatchsize 2147473647
-commitbatchsize 100
-commitbatchthreshold 1000
-keepalivemessageinterval 300
-logintimeout 15
-maxbcpthreads 1
-maxdeliveredtransactions 0
-pollinginterval 5000
-querytimeout 1800
-transactionsperhistory 100
2020-09-17 17:53:46.552 Connecting to Subscriber 'DBREPV02'
2020-09-17 17:53:46.599 Initializing
2020-09-17 17:58:49.058 Delivering replicated transactions
2020-09-17 17:58:49.120 <stats state="2" fetch="0" wait="302" cmds="352" callstogetreplcmds="1"><sincelaststats elapsedtime="302" fetch="0" wait="302" cmds="352" cmdspersec="1.000000"/><message>Raised events that occur when an agent's reader thread waits longer than the agent's -messageinterval time. (By default, the time is 60 seconds.) If you notice State 2 events that are recorded for an agent, this indicates that the agent is taking a long time to write changes to the destination.</message></stats>
2020-09-17 18:06:03.535 Delivering replicated transactions
2020-09-17 18:06:03.551 <stats state="2" fetch="0" wait="736" cmds="649" callstogetreplcmds="1"><sincelaststats elapsedtime="434" fetch="0" wait="434" cmds="297" cmdspersec="0.000000"/><message>Raised events that occur when an agent's reader thread waits longer than the agent's -messageinterval time. (By default, the time is 60 seconds.) If you notice State 2 events that are recorded for an agent, this indicates that the agent is taking a long time to write changes to the destination.</message></stats>
2020-09-17 18:12:59.677 Delivering replicated transactions
2020-09-17 18:12:59.693 <stats state="2" fetch="0" wait="1153" cmds="946" callstogetreplcmds="1"><sincelaststats elapsedtime="416" fetch="0" wait="416" cmds="297" cmdspersec="0.000000"/><message>Raised events that occur when an agent's reader thread waits longer than the agent's -messageinterval time. (By default, the time is 60 seconds.) If you notice State 2 events that are recorded for an agent, this indicates that the agent is taking a long time to write changes to the destination.</message></stats>
2020-09-17 18:15:45.269 5 transaction(s) with 1027 command(s) were delivered.
2020-09-17 18:19:51.526 Delivering replicated transactions
2020-09-17 18:19:51.589 <stats state="2" fetch="0" wait="1564" cmds="4664" callstogetreplcmds="1"><sincelaststats elapsedtime="411" fetch="0" wait="411" cmds="3718" cmdspersec="9.000000"/><message>Raised events that occur when an agent's reader thread waits longer than the agent's -messageinterval time. (By default, the time is 60 seconds.) If you notice State 2 events that are recorded for an agent, this indicates that the agent is taking a long time to write changes to the destination.</message></stats>

SQL Server
SQL Server
A family of Microsoft relational database management and analysis systems for e-commerce, line-of-business, and data warehousing solutions.
8,499 questions
No comments
{count} votes

Accepted answer
  1. Kathy Gibson 96 Reputation points
    2020-09-18T18:26:57.597+00:00

    The delay was caused by a long running delete on a user table in the subscriber db.

    This was solved by updating statistics and reorganizing indexes for that table.

    Then I put a maintenance plan in place for the entire database so that it doesn't happen again.

    No comments

0 additional answers

Sort by: Most helpful