Using “Verbose history agent profile.” while troubleshooting Replication

The “default” Agent Profile enables “-HistoryVerboseLevel 1” which provides limited detail in the Distribution database history tracking tables. Using Replication Agent Profile “Verbose history agent profile.” enables “-HistoryVerboseLevel 2” which provides additional diagnostic data while troubleshooting SQL Server Replication.  The “Verbose history agent profile.” can be set using Replication Monitor for all types of SQL Replication Agent. Use the “verbose” setting while troubleshooting connectivity or agent performance problem.  Once resolved, set the Profile back to “default” to reduce Agent tracking overhead.

The detailed Agent history and runtime statistics can also be written to a TEXT file using the “-output” parameter. See KB article 312292 How to enable replication agents for logging to output files in SQL Server.

How to enable “Verbose history agent profile.”

In Replication Monitor “right-click” a Replication Agent and select “Agent Profile”.

Click on “Verbose history agent profile.” to enable detailed logging by the Replication Agent.  You will need to stop and restart the Replication Agent for the setting to take effect.

Click the details “. . . “ button to review the Agent Profile settings.

As shown in the screen shot below, selecting “View Details” after setting “Verbose history agent profile.” provides detailed agent run history along with an Agent summary recorded every 10 minutes.

Select the “STATISTICS SINCE AGENT STARTED”, then CTRL-C to copy stats to clipboard.  Then PASTE into Notepad.exe.

The detailed Agent statistics can be used to troubleshoot SQL Server Replication performance.  See Troubleshooting Transactional Replication for more details on using Agent Statistics along with other performance monitoring tools for troubleshooting SQL Server Replication.

logread.exe <job parameters>

Statistics appear automatically when executing, then stopping LogRead.exe via CMD-prompt providing immediate feedback on throughput while adjusting Log Reader parameters.  Output includes a breakout by article showing table\article and type of command was being processed by the Log Reader.

With SQL Agent Log Reader job stopped, paste the job parameters along with LogRead.exe into admin cmd-prompt>: C:\Program Files\Microsoft SQL Server\130\COM\logread.exe <SQL Agent job parameters>

Allow Log Reader to run for period of time, then stop with CTRL-C, statistics appear in the cmd-console.

Sample Log Reader Agent Output
******************** STATISTICS SINCE AGENT STARTED ***************************
Execution time (ms): 736234                     --- about 12 minutes
Work time (ms): 736093
Distribute Repl Cmds Time(ms): 730371
Fetch time(ms): 562083                           --- Fetch time == Write time (*balanced*)
Repldone time(ms): 1584
Write time(ms): 530380                           --- Write Time
   Num Trans: 187876 Num Trans/Sec: 255.234053
   Num Cmds: 25353045 Num Cmds/Sec: 34454.920   --- 25 million commands

Article Level Parameterized Command Stats
Article Id: 1
Number of Inserts: 203
Number of Updates: 345
Number of Deletes: 0
Number of Other Cmds (e.g. custom commands): 0
Article Id: 2
Number of Inserts: 12478600
Number of Updates: 0
Number of Deletes: 12185700
Number of Other Cmds (e.g. custom commands): 0
Article Id: 3
Number of Inserts: 125
Number of Updates: 0
Number of Deletes: 0
Number of Other Cmds (e.g. custom commands): 0

Distrib.exe <job parameters>

Sample Distribution Agent
************************ STATISTICS SINCE AGENT STARTED ***********************
07-13-2010 22:26:56 

Total Run Time (ms) : 300797     Total Work Time  : 109
Total Num Trans     : 2     Num Trans/Sec    : 18.35
Total Num Cmds      : 6     Num Cmds/Sec     : 55.05
Total Idle Time     : 300000 

Writer Thread Stats
Total Number of Retries   : 0
Time Spent on Exec        : 78
Time Spent on Commits (ms): 359     Commits/Sec         : 458.72
Time to Apply Cmds (ms)   : 109     Cmds/Sec            : 55.05
Time Cmd Queue Empty (ms) : 532     Empty Q Waits > 10ms: 2
Total Time Request Blk(ms): 300532
P2P Work Time (ms)        : 0     P2P Cmds Skipped    : 0 

Reader Thread Stats
Calls to Retrieve Cmds    : 63
Time to Retrieve Cmds (ms): 109     Cmds/Sec            : 55.05
Time Cmd Queue Full (ms)  : 0     Full Q Waits > 10ms : 0