Calculating Network Latency Between Always On Availability Group Replicas

We had a business requirement to add a cloud-based asynchronous replica to an on-premises SQL Server Always On Availability Group. After adding a high-volume database to the Availability Group, we noticed that the log send queue started growing rapidly.

Our initial suspicion was that network latency between the on-premises primary replica and the cloud replica was contributing to the problem. However, before requesting a network upgrade, we needed a way to prove that network performance was actually affecting data movement.

One useful approach is to use the Always On data movement Extended Events trace described in Microsoft's article:

Troubleshooting data movement latency between synchronous-commit AlwaysOn Availability Groups

Although Microsoft's example focuses on a synchronous-commit replica, the same data movement events can be used to investigate an asynchronous replica, with some important differences.

The First Symptom: A Growing Send Queue

The first indication was that the log send queue was significantly larger than the redo queue.

For example:

SELECT
    ar.replica_server_name AS ReplicaName,
    DB_NAME(drs.database_id) AS DatabaseName,
    drs.log_send_queue_size AS LogSendQueueKB,
    drs.redo_queue_size AS RedoQueueKB
FROM sys.dm_hadr_database_replica_states drs
JOIN sys.availability_replicas ar
    ON drs.replica_id = ar.replica_id
WHERE DB_NAME(drs.database_id) = 'DB1';

The result looked like this:

ReplicaName	DatabaseName	LogSendQueueKB	RedoQueueKB
SQL1	DB1	79,604,352	88

The important observation is the difference between the two queues. The send queue was approximately 76 GB, while the redo queue was only 88 KB.

This suggested that the secondary was not primarily struggling to redo the log it had already received. Instead, a significant amount of log was accumulating before it could be delivered to the secondary.

That made network throughput or latency a strong candidate for further investigation.

Capturing the Data Movement Trace

The next step was to capture an Always On data movement trace on both the primary and secondary replicas.

It is important to run the trace for approximately the same period on both servers so that the events can be correlated.

In our case, we captured the trace for 2 minutes and 30 seconds.

IF EXISTS
(
    SELECT *
    FROM sys.server_event_sessions
    WHERE name = 'AlwaysOn_Data_Movement_Tracing'
)
BEGIN
    DROP EVENT SESSION [AlwaysOn_Data_Movement_Tracing]
    ON SERVER;
END
GO

CREATE EVENT SESSION [AlwaysOn_Data_Movement_Tracing] ON SERVER
ADD EVENT sqlserver.hadr_apply_log_block,
ADD EVENT sqlserver.hadr_capture_filestream_wait,
ADD EVENT sqlserver.hadr_capture_log_block,
ADD EVENT sqlserver.hadr_capture_vlfheader,
ADD EVENT sqlserver.hadr_db_commit_mgr_harden,
ADD EVENT sqlserver.hadr_log_block_compression,
ADD EVENT sqlserver.hadr_log_block_decompression,
ADD EVENT sqlserver.hadr_log_block_group_commit,
ADD EVENT sqlserver.hadr_log_block_send_complete,
ADD EVENT sqlserver.hadr_lsn_send_complete,
ADD EVENT sqlserver.hadr_receive_harden_lsn_message,
ADD EVENT sqlserver.hadr_send_harden_lsn_message,
ADD EVENT sqlserver.hadr_database_flow_control_action,
ADD EVENT sqlserver.hadr_transport_flow_control_action,
ADD EVENT ucs.ucs_connection_flow_control,
ADD EVENT sqlserver.hadr_transport_receive_log_block_message,
ADD EVENT sqlserver.log_block_pushed_to_logpool,
ADD EVENT sqlserver.log_flush_complete,
ADD EVENT sqlserver.recovery_unit_harden_log_timestamps
ADD TARGET package0.event_file
(
    SET filename = N'E:\AlwaysOn_Data_Movement_Tracing.xel',
        max_file_size = (500),
        max_rollover_files = (4)
)
WITH
(
    MAX_MEMORY = 4096 KB,
    EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
    MAX_DISPATCH_LATENCY = 30 SECONDS,
    MAX_EVENT_SIZE = 0 KB,
    MEMORY_PARTITION_MODE = NONE,
    TRACK_CAUSALITY = OFF,
    STARTUP_STATE = ON
);
GO

ALTER EVENT SESSION [AlwaysOn_Data_Movement_Tracing]
ON SERVER STATE = START;

WAITFOR DELAY '00:02:30';

ALTER EVENT SESSION [AlwaysOn_Data_Movement_Tracing]
ON SERVER STATE = STOP;
GO

Important: Extended Events can generate a significant amount of data on a busy SQL Server. Keep the capture window as short as practical and monitor the size of the .xel files.

Finding a Log Block to Correlate

Once the trace has been collected, we need to identify the database in the trace.

On the secondary replica, run:

SELECT group_database_id
FROM sys.availability_databases_cluster
WHERE database_name = 'DB1';

In our example, the result was:

group_database_id
------------------------------------
3F5E2823-002E-46FD-A971-869ED3892B27

We can use this value to locate events associated with DB1 in the Extended Events output.

For example, the secondary trace contained events like these:

name	timestamp	database_replica_id	mode	log_block_id
hadr_transport_receive_log_block_message	2026-08-04 09:20:17.2059851	3F5E2823-002E-46FD-A971-869ED3892B27	2	28346698302255272
hadr_apply_log_block	2026-08-04 09:20:17.2060235	3F5E2823-002E-46FD-A971-869ED3892B27	2	28346698302255032
hadr_transport_receive_log_block_message	2026-08-04 09:20:17.2060465	3F5E2823-002E-46FD-A971-869ED3892B27	1	28346698302255392
hadr_apply_log_block	2026-08-04 09:20:17.2060554	3F5E2823-002E-46FD-A971-869ED3892B27	2	28346698302255152
hadr_transport_receive_log_block_message	2026-08-04 09:20:17.2060730	3F5E2823-002E-46FD-A971-869ED3892B27	1	28346698302255512
hadr_transport_receive_log_block_message	2026-08-04 09:20:17.2060836	3F5E2823-002E-46FD-A971-869ED3892B27	2	28346698302255392
hadr_apply_log_block	2026-08-04 09:20:17.2060849	3F5E2823-002E-46FD-A971-869ED3892B27	2	28346698302255272

Pick a log_block_id, preferably one toward the latter part of the trace. This increases the chance that the same log block was captured in both the primary and secondary traces.

For this example, we selected:

28346698302255392

Searching for the Log Block on the Secondary

Searching for that log block ID on the secondary produced the following results:

name	timestamp	database_replica_id	mode	log_block_id
hadr_transport_receive_log_block_message	2026-08-04 09:20:17.2060465	3F5E2823-002E-46FD-A971-869ED3892B27	1	28346698302255392
hadr_transport_receive_log_block_message	2026-08-04 09:20:17.2060836	3F5E2823-002E-46FD-A971-869ED3892B27	2	28346698302255392
hadr_log_block_decompression	2026-08-04 09:20:17.2061251	NULL	NULL	28346698302255392
hadr_log_block_decompression	2026-08-04 09:20:17.2061274	NULL	NULL	28346698302255392
hadr_apply_log_block	2026-08-04 09:20:17.2061456	3F5E2823-002E-46FD-A971-869ED3892B27	2	28346698302255392
log_block_pushed_to_logpool	2026-08-04 09:20:17.2063843	NULL	NULL	28346698302255392
log_flush_complete	2026-08-04 09:20:17.2068296	NULL	NULL	28346698302255392

Searching for the Same Log Block on the Primary

Next, search the primary trace for the same log_block_id:

28346698302255392

The relevant events were:

name	timestamp	database_replica_id	availability_replica_id	log_block_id
hadr_capture_log_block	2026-08-04 09:19:07.1730670	3F5E2823-002E-46FD-A971-869ED3892B27	D91DF70A-8226-4022-93F6-12F4D5B77699	28346698302255392
hadr_capture_filestream_wait	2026-08-04 09:19:07.1730674	3F5E2823-002E-46FD-A971-869ED3892B27	D91DF70A-8226-4022-93F6-12F4D5B77699	28346698302255392
hadr_capture_log_block	2026-08-04 09:19:07.1730690	3F5E2823-002E-46FD-A971-869ED3892B27	D91DF70A-8226-4022-93F6-12F4D5B77699	28346698302255392
hadr_capture_log_block	2026-08-04 09:20:16.6305401	3F5E2823-002E-46FD-A971-869ED3892B27	D91DF70A-8226-4022-93F6-12F4D5B77699	28346698302255392
hadr_capture_log_block	2026-08-04 09:20:16.6305465	3F5E2823-002E-46FD-A971-869ED3892B27	D91DF70A-8226-4022-93F6-12F4D5B77699	28346698302255392
hadr_log_block_compression	2026-08-04 09:20:16.6307262	NULL	D91DF70A-8226-4022-93F6-12F4D5B77699	28346698302255392
hadr_log_block_send_complete	2026-08-04 09:20:16.9981083	NULL	NULL	28346698302255392

The darker gray row is the key event we need from the primary replica: hadr_log_block_send_complete.

Asynchronous Replicas Have Some Important Differences

One important detail is that the events captured for an asynchronous replica differ slightly from those shown in Microsoft's example for a synchronous replica.

With asynchronous replication, the primary compresses the log blocks before sending them, and the secondary decompresses them after receiving them.

As a result, we can see:

• hadr_log_block_compression on the primary
• hadr_log_block_decompression on the secondary

There is also an important difference in how the primary waits for the secondary.

With an asynchronous replica, the primary does not wait for the secondary to harden the log block before continuing. Therefore, we should not expect to see the same hadr_receive_harden_lsn_message round-trip used in the synchronous-commit example.

This makes the primary-to-secondary portion of the data movement particularly useful when investigating network latency for an asynchronous replica.

The Events We Need to Calculate Network Latency

The two events we are interested in are:

Primary Replica

hadr_log_block_send_complete

2026-08-04 09:20:16.9981083

Secondary Replica

hadr_transport_receive_log_block_message

2026-08-04 09:20:17.2060465

Both events correspond to the same log block:

28346698302255392

Calculating the Network Latency

We can calculate the difference between these timestamps using DATEDIFF:

SELECT DATEDIFF(
    millisecond,
    '2026-08-04 09:20:16.9981083',
    '2026-08-04 09:20:17.2060465'
);

The result is approximately: 208

In other words, the elapsed time between the primary reporting the log block as sent and the secondary reporting that it received the log block was approximately 208 milliseconds.

Conclusion

This gave us a much stronger data point than simply saying, "the network seems slow."

We were able to correlate the same log_block_id across the primary and secondary replicas and measure the elapsed time between the hadr_log_block_send_complete event on the primary and the hadr_transport_receive_log_block_message event on the secondary.

In this example, that measurement was approximately 208 milliseconds.

Combined with the rapidly growing send queue and relatively small redo queue, the trace provided evidence that network performance was a significant factor in the asynchronous replica's ability to keep up with the primary.

That data gave us the evidence we needed to justify a network upgrade rather than treating the problem as a general SQL Server performance issue.

References

• Microsoft SQL Server: Troubleshooting data movement latency between synchronous-commit AlwaysOn Availability Groups

Anatomy of a SQL Server CDC Cleanup Job (and How to Keep It Healthy)

Change Data Capture (CDC) is great—until it isn’t. Under heavy change volume, the CDC cleanup job may fall behind. When that happens, Change Tables (CTs) grow rapidly, and the cleanup job can block the capture job, which can in turn delay or stall downstream consumers. 

This post explains: how to quickly estimate CT growth, how the cleanup job actually deletes rows, and the three main tuning knobs to keep CDC stable. 

Quick Health Check: Approximate CT Row Counts 

To get a fast row-count estimate of each CDC Change Table:

SELECT
c.object_id,
t.name,
p.rows
FROM cdc.change_tables c
JOIN sys.tables t
ON c.object_id = t.object_id
JOIN sys.partitions p
ON t.object_id = p.object_id
WHERE p.index_id IN (0,1)
ORDER BY c.object_id;

Example output:

object_id     name                   rows
-----------   ---------------------  --------
82099333      dbo_customer_CT         167702
98099390      dbo_district_CT         270010
114099447     dbo_item_CT             0
370100359     dbo_new_order_CT        134634
386100416     dbo_warehouse_CT        135522
562101043     dbo_order_line_CT       2018297
578101100     dbo_stock_CT            1343322
1973582069    dbo_orders_CT           191732
--------------------------------------------
Total                                 4,261,219

CDC Cleanup Defaults (Retention + Threshold) 

CDC cleanup behavior is driven mainly by: 

• Retention (how long CT rows are kept) 
• Threshold (rows deleted per batch) 

Check current settings:

EXEC sys.sp_cdc_help_jobs;

Example output:

job_type  job_name           retention  threshold
--------  -----------------  ---------  ---------
capture   cdc.tpcc_capture          0          0
cleanup   cdc.tpcc_cleanup       4320       5000

Defaults: Retention = 4320 minutes (72 hours / 3 days) 

Threshold = 5000 rows per delete batch 

What the Cleanup Job Actually Does 

Extended Events typically reveals that the cleanup job processes CTs sequentially via a cursor:

DECLARE #hchange_table CURSOR LOCAL FAST_FORWARD
FOR
SELECT capture_instance, start_lsn
FROM [cdc].[change_tables]
WHERE (@capture_instance IS NULL)
OR (capture_instance = @capture_instance);

Because cdc.change_tables is clustered by object_id, it tends to delete CTs in object_id order. With @p1 = 5000 (threshold), you’ll often see patterns like:

DELETE TOP (@p1) FROM [cdc].[dbo_customer_CT]    WHERE __$start_lsn @p2 (35 times)
DELETE TOP (@p1) FROM [cdc].[dbo_district_CT]    WHERE __$start_lsn @p2 (56 times)
...
DELETE TOP (@p1) FROM [cdc].[dbo_stock_CT]       WHERE __$start_lsn @p2 (323 times)

Large tables can dominate runtime and prevent cleanup from ever catching up. 

The Three Tuning Knobs

1) Adjust the Threshold 

Higher threshold = deletes more per batch (often more efficient), but can increase contention. 

Lower threshold = smaller deletes, but more loops and potentially longer runtime. 

Example:

EXEC sys.sp_cdc_change_job
@job_type  = N'cleanup',
@threshold = 2000;

2) Reduce Retention 

Reducing retention means less data to keep, making cleanup easier. But consumers must be able to ingest changes within the retention window. Example (2160 minutes = 36 hours):

EXEC sys.sp_cdc_change_job
@job_type = N'cleanup',
@retention  = 2160;

3) Run Cleanup More Frequently 

First, find the schedule ID:

USE msdb;
GO
SELECT j.name AS job_name,
s.schedule_id,
s.name AS schedule_name
FROM dbo.sysjobs j
JOIN dbo.sysjobschedules js
ON j.job_id = js.job_id
JOIN dbo.sysschedules s
ON js.schedule_id = s.schedule_id
WHERE j.name = N'cdc.tpcc_cleanup';

Then update it (e.g., every 15 minutes):

USE msdb;
GO
EXEC dbo.sp_update_schedule
@schedule_id = 171,      -- from query above
@enabled = 1,
@freq_type = 4,          -- daily
@freq_interval = 1,
@freq_subday_type = 4,   -- minutes
@freq_subday_interval = 15,
@active_start_time = 000000; -- midnight

Last Resort: Truncating CT Tables (High Risk) 

If cleanup still can’t keep up, truncating CT tables may be the fastest recovery path—but it irreversibly deletes change history.

Safe sequence:

1. Stop the capture job
2. Ensure consumers ingest remaining changes
3. Truncate CT tables
4. Restart capture job 

Warnings:

• You may create data gaps for downstream consumers.
• Consumers may need a full reload/re-baseline after truncation.
• Do this only with stakeholder approval and a clear recovery plan.

Not Able to Add Article or Subscription After Upgrading

In SQL 2022, there is change in the linked server format used by replication for the listener subscriber with non default port, as shown below, the old format name is LISTENER,54321 and the new format is LISTENER and the port is in the provider string select name, provider_string from sys.servers

name              provider_string
LISTENER,54321    NULL
LISTENER          addr=tcp:LISTENER,54321

After the upgrade to SQL 2022 a couple of behaviors where observed: 

The first one is adding an article to a publication of a subscriber using the old format won’t generate a snapshot: A snapshot was not generated because no subscription needed initialization 

The second one is creating a new publication for an existing subscriber in the old format will get this error:

'SQL1' is not defined as a Subscriber for 'SQL2'. Could not update the distribution database subscription table. The subscription status could not be changed. The subscription could not be created. The subscription could not be found. Changed database context to 'dummy'. (Microsoft SQL Server, Error: 20032) 

Or 

Cannot insert the value NULL into column ‘freq_subday_interval’, table ‘distribution.dbo.MSrepl_agent_jobs’; column doen not allow nulls. UPDATE fails. Could not update the distribution database subscription table. The subscription status could not be changed. The subscription could not be created. The subscription could not be found. Changed database context to 'dummy'. (Microsoft SQL Server, Error: 20032) 

The workaround is to enable TF 15005 in both the publisher and distributor as well as creating aliases for the listener subscribers with non default port numbers, example LISTENER3 

If publisher and distributor are AG then aliases for the listener publisher and listener distributor are also needed, LISTENER1 and LISTENER2, respectively, in both 32 and 64-bit SQL Native Client, as shown below, in a PowerShell script

$aliases = @(
   @{name = 'LISTENER1'; value = 'DBMSSOCN,LISTENER1,54321'}
   @{name = 'LISTENER2'; value = 'DBMSSOCN,LISTENER2,54321'}
   @{name = 'LISTENER3'; value = 'DBMSSOCN,LISTENER3,54321'}
)

$registryPaths = @(
   'HKLM:\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo'
   'HKLM:\SOFTWARE\WOW6432Node\Microsoft\MSSQLServer\Client\ConnectTo'
)
foreach ($alias in $aliases) {
   foreach ($registryPath in $registryPaths) {
      if (-not (Test-Path $registryPath)) {
          New-Item -Path $registryPath -Force
      }
      New-ItemProperty -Path $registryPath -Name $alias.name `
      -Value $alias.value -PropertyType String -Force
   }
}

Then you should be able to add the article or to create the subscription without specifying the port number

Automating Major SQL Version Upgrade with DBATools

You can easily automate a major version upgrade, for example to SQL 2022, using Install-DbaInstance from the DBATools PowerShell module. As of this writing, there was not a documented example, so I played around with it and figured it out. 

If you use the configuration parameter option

$config = @{
    ACTION="Upgrade"
}

You will get this error: The setting 'FEATURES' is not allowed when the value of setting 'ACTION' is 'Upgrade'. The workaround is to use a configuration file to override the FEATURES option that the configuration parameter adds by default.  The configuration file must have a least these three options: ACTION, INSTANCENAME, and QUIET

The following example does a remote upgrade of a named instance to SQL 2022 

$options = '
[OPTIONS]
ACTION="Upgrade"
INSTANCENAME="instance_name"
QUIET="True"
'
Set-Content -Path 'c:\temp\config.ini' -Value $options
 
$paramsUpgrade = @{
    ComputerName      = 'computer_name'
    Version           = '2022'
    Path              = 'sql_install_path’
    UpdateSourcePath  = 'sql_cu_path’
    ConfigurationFile = 'c:\temp\config.ini'
    Restart           = $true
    Credential        = Get-Credential
    Confirm           = $false
}
Install-DbaInstance @paramsUpgrade

An Exception Occurred in SMO While Trying to Manage a Service

One way to automate SQL tasks is by using SMO, but sometimes when there are multiple SQL versions installed or uninstalled it may be corrupted and you may get "An exception occurred in SMO while trying to manage a service..." when using PowerShell or “Cannot connect to WMI provider. You do not have permission or the server in unreachable…” when using SQL Server Configuration Manager. In this post I will show you how to easily fix it. 

To use SMO with PowerShell, first you need to load the assembly

   

[System.Reflection.Assembly]::LoadWithPartialName('Microsoft.SqlServer.SqlWmiManagement') | Out-Null

Next, you can create an instance of the .Net object, providing the name of the server, e.g. PABLITO

   

$s = New-Object Microsoft.SqlServer.Management.Smo.Wmi.ManagedComputer PABLITO
$s

ConnectionSettings : Microsoft.SqlServer.Management.Smo.Wmi.WmiConnectionInfo
Services           :
ClientProtocols    :
ServerInstances    :
ServerAliases      :
Urn                : ManagedComputer[@Name='PABLITO']
Name               : PABLITO
Properties         : {}
UserData           :
State              : Existing

Note that in the results above, services is blank, so when you reference it, you will get the error

   

$s.Services

The following exception occurred while trying to enumerate the collection:
"An exception occurred in SMO while trying to manage a service.".
At line:1 char:1
+ $s.Services
+ ~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [], ExtendedTypeSystemException
    + FullyQualifiedErrorId : ExceptionInGetEnumerator

The fix is to compile the sqlmgmproviderxpsp2up.mof of the highest SQL version installed in the machine. You can quickly search the path of the .mof, order by Creation Date, and displaying the Directory name

   

Get-ChildItem "c:\program files (x86)\Microsoft SQL Server\*\Shared\sqlmgmproviderxpsp2up.mof" |
Sort-Object CreationTime |
Select-Object Directory
 
Directory
---------
C:\program files (x86)\Microsoft SQL Server\90\Shared
C:\program files (x86)\Microsoft SQL Server\100\Shared
C:\program files (x86)\Microsoft SQL Server\110\Shared

You can see that this machine has three SQL versions installed SQL 2005, 2008, and 2012 (Yes I still support those old versions but not by choice) To get the highest version, you just need to add -Last 1 and assign the result to the variable $i to execute mofcomp

   

$i = Get-ChildItem "c:\program files (x86)\Microsoft SQL Server\*\Shared\sqlmgmproviderxpsp2up.mof" |
Sort-Object CreationTime |
Select-Object Directory -Last 1

mofcomp "$($i.Directory)\sqlmgmproviderxpsp2up.mof"

Microsoft (R) MOF Compiler Version 6.1.7600.16385
Copyright (c) Microsoft Corp. 1997-2006. All rights reserved.
Parsing MOF file: C:\program files (x86)\Microsoft SQL Server\110\Shared\sqlmgmproviderxpsp2up.mof
MOF file has been successfully parsed
Storing data in the repository...
Done!

Now you can get the services with no errors

   

[System.Reflection.Assembly]::LoadWithPartialName('Microsoft.SqlServer.SqlWmiManagement') | Out-Null
$s = New-Object Microsoft.SqlServer.Management.Smo.Wmi.ManagedComputer PABLITO
$s.Services

Monitoring Identity Column Values

Identity columns are often used for generating key values. Once create it, we often forget about it. However, once the max value allowed by the data type is reached, no more rows can be inserted.

To avoid unexpected outage, we can use sys.identity_columns to monitor if the values are approaching the max limit.  The 6 data types supported are: tinyint, smallint, int, bigint, numeric, and decimal.

For example, we can create 3 tables with identity columns, assign a seed value, and insert some data

create table paul_test1 (a tinyint identity, b char(1))
create table paul_test2 (a int identity, b char(1))
create table paul_test3 (a numeric(6,0) identity, b char(1))

dbcc checkident('paul_test1', reseed, 200)
dbcc checkident('paul_test2', reseed, 2000000000)
dbcc checkident('paul_test3', reseed, 999999)

insert paul_test1 (b) values ('x')
insert paul_test2 (b) values ('x')
insert paul_test3 (b) values ('x')

If we insert one more row on the third table

insert paul_test3 (b) values ('x')

We will get this error:

Msg 8115, Level 16, State 1, Line 62 Arithmetic overflow error converting IDENTITY to data type numeric. Arithmetic overflow occurred.

We can query sys.identity_columns to find the identity column last value of a table and calculate the percent used of the positive values. Then we can run the query on each database using sp_MSforeachdb, as shown on the script below (e.g. C:\TEMP\identity_values.sql)

create table #monitor_identity(
instance_name varchar(255)
,database_name varchar(255)
,table_name varchar(255) 
,schema_name varchar(255)
,column_name varchar(255) 
,current_value numeric(38)
,max_value numeric(38)
,pct_used numeric(38,2)
)
insert #monitor_identity
exec sp_MSforeachdb '
select 
@@servername
,''?''
,object_schema_name(object_id, db_id(''?''))
,object_name(object_id, db_id(''?''))
, name
, cast(last_value as numeric(38))
, max_value = case TYPE_NAME(system_type_id)
when ''tinyint'' then 255
when ''smallint'' then 32767
when ''int'' then 2147483647
when ''bigint'' then 9223372036854775807
when ''numeric'' then cast(replicate(''9'',precision) as numeric(38))
when ''decimal'' then cast(replicate(''9'',precision) as numeric(38))
end
, pct_used = cast(last_value as numeric(38)) / case TYPE_NAME(system_type_id)
when ''tinyint'' then 255
when ''smallint'' then 32767
when ''int'' then 2147483647
when ''bigint'' then 9223372036854775807
when ''numeric'' then cast(replicate(''9'',precision) as numeric(38))
when ''decimal'' then cast(replicate(''9'',precision) as numeric(38))
end * 100
from ?.sys.identity_columns with (nolock)
where last_value is not null
'
select
instance_name  
,database_name 
,schema_name 
,table_name 
,column_name 
,current_value 
,max_value 
,pct_used 
from #monitor_identity
where pct_used > 70
order by 
database_name 
,schema_name 
,table_name 
drop table #monitor_identity

Output

To run the script in multiple instances, we can have a list of instances in a text file (e.g. C:\TEMP\instance_list.txt)

instance1
instance2

Then we can easily use a PowerShell script to pipe the instance list content to Invoke-Sqlcmd, and pipe to Out-GridView

Get-Content C:\TEMP\instance_list.txt | Invoke-Sqlcmd -InputFile C:\TEMP\identity_values.sql | Out-GridView

Distribution Cleanup Job Blocking

The distribution cleanup job may block the log reader agent for several minutes, if there is a large number of rows to keep and "delete TOP N" deletes N-1 rows.

The Delete TOP N Behavior

When there are N or N+1 rows, delete TOP N stops scanning the range once N rows are reached
When there are N-1 rows, delete TOP N will scan the entire range. If the range contains a very large amount rows then the scan may take long time, and the locks will be held until the scan finishes, which can cause blocking.

For example, the distribution cleanup job calls the delete statements in a "WHILE 1 =1" loop from the following stored procedures

-- sp_MSdelete_publisherdb_trans line 202:
delete TOP(2000) MSrepl_commands WITH (PAGLOCK) from MSrepl_commands with (INDEX(ucMSrepl_commands))

-- sp_MSdelete_dodelete line 38:
delete TOP(5000) MSrepl_transactions WITH (PAGLOCK) from MSrepl_transactions with (INDEX(ucMSrepl_transactions))

The following extended event session can be used to get the query plans for line 202 and 38 of the respective stored procedures

CREATE EVENT SESSION [distribution_cleanup] ON SERVER 
ADD EVENT sqlserver.query_post_execution_showplan(
    ACTION(sqlserver.query_plan_hash,sqlserver.tsql_stack)
    WHERE (([object_name]=N'sp_MSdelete_publisherdb_trans' 
 AND [sqlserver].[like_i_sql_unicode_string]([sqlserver].[tsql_stack],N'%frame level=''1''%line=''202''%frame level=''2''%') 
 OR ([object_name]=N'sp_MSdelete_dodelete'
 AND [sqlserver].[like_i_sql_unicode_string]([sqlserver].[tsql_stack],N'%frame level=''1''%line=''38''%frame level=''2''%'))))),
ADD EVENT sqlserver.sp_statement_completed(SET collect_object_name=(1),collect_statement=(1)
    ACTION(sqlserver.query_plan_hash,sqlserver.tsql_stack)
    WHERE (([object_name]=N'sp_MSdelete_publisherdb_trans' 
 AND [sqlserver].[like_i_sql_unicode_string]([sqlserver].[tsql_stack],N'%frame level=''1''%line=''202''%frame level=''2''%') 
 OR ([object_name]=N'sp_MSdelete_dodelete'
 AND [sqlserver].[like_i_sql_unicode_string]([sqlserver].[tsql_stack],N'%frame level=''1''%line=''38''%frame level=''2''%')))))
ADD TARGET package0.event_file(SET filename=N'c:\temp\distribution_cleanup.xel')
WITH (TRACK_CAUSALITY=ON)
GO

In this particular case, the table MSrepl_commands had about 600 million rows, each iteration deletes 2,000 rows with a few milliseconds of duration, but the last iteration deleted 1,352 rows with a 19 minute duration

The following query can be used to extract the query plan from the .xel file, so we can just use SSMS to visualize it

SELECT event_data = CONVERT(XML, event_data)
INTO #tmp
FROM sys.fn_xe_file_target_read_file( N'C:\temp\distribution_cleanup_0_131593922293630000*.xel', NULL, NULL, NULL);

SELECT 
t.event_data.value('(/event/@timestamp)[1]', 'datetime2') AS event_time
,t.event_data.value('(/event/data[@name="duration"]/value)[1]', 'bigint') AS duration
,t.event_data.value('(/event/data[@name="object_name"]/value)[1]', 'varchar(255)') AS object_name
,actual_plan = x.xml_fragment.query('.')
FROM #tmp AS t
CROSS APPLY t.event_data.nodes(N'/event/data[@name="showplan_xml"]/value/*')
AS x(xml_fragment)
order by event_time 

Comparing the query plan when it deletes 2,000 rows vs. the plan that deletes 1.356 rows, the former reads 2,000 rows and the latter reads more than 200 million rows due to the residual predicate

This explains why the lock is held for a long time, and the blocking is explained by the cluster index definition shown below

The Cluster Index

Both tables MSrepl_commands and MSrepl_transaction have a similar cluster index that has the publisher_database_id as the leading key column. Thus, rows are stored in order by publisher_database_id. An example for MSrepl_transactions is shown below

If there is more than one publisher_database_id then the last page of the first publisher_database_id range will contain not only the newest rows for the first publisher_database_id but also the oldest rows for the second publisher_database_id. So, the delete with (PAGLOCK) of the oldest rows for the second publisher_database_id will block the insert of new rows by the log reader for the first publisher_database_id .

Example

In my test environment two publisher databases pub1 and pub2, have publisher_database_id = 3 and publisher_database_id = 4 respectively.

-- create databases
use master
create database pub1
create database pub2
go

-- create tables
use pub1
create table test1(a int not null identity, b datetime, c varchar(255)
constraint test1_pk primary key (a)
)
use pub2
create table test2(a int not null identity, b datetime, c varchar(255)
constraint test2_pk primary key (a)
)
GO

-- Adding the transactional publication with immediate synch
use [pub1]
exec sp_replicationdboption @dbname = N'pub1', @optname = N'publish', @value = N'true'
exec sp_addpublication @publication = N'test_pub1', @allow_anonymous = N'true', @immediate_sync = N'true', @independent_agent = N'true', @status = N'active'
exec sp_addpublication_snapshot @publication = N'test_pub1', @frequency_type = 1
exec sp_addarticle @publication = N'test_pub1', @article = N'test1', @source_owner = N'dbo', @source_object = N'test1'
GO

-- Adding the transactional publication with immediate synch
use [pub2]
exec sp_replicationdboption @dbname = N'pub2', @optname = N'publish', @value = N'true'
exec sp_addpublication @publication = N'test_pub2', @allow_anonymous = N'true', @immediate_sync = N'true', @independent_agent = N'true', @status = N'active'
exec sp_addpublication_snapshot @publication = N'test_pub2', @frequency_type = 1
exec sp_addarticle @publication = N'test_pub2', @article = N'test2', @source_owner = N'dbo', @source_object = N'test2'
GO

-- disable distribution cleanup job
exec msdb..sp_update_job @job_name = 'Distribution clean up: distribution', @enabled = 0

-- add 5999 rows at 2:43 PM
use pub2
insert test2(b,c)
values (getdate(),replicate('x',200))
go 5999

-- add 21000 rows at 3:44 PM (one hour later)
use pub1
insert test1(b,c)
values (getdate(),replicate('x',200))
go 1000

use pub2
insert test2(b,c)
values (getdate(),replicate('x',200))
go 20000

-- verify there is 26999 rows
use distribution
select count(*) from MSrepl_transactions
select count(*) from MSrepl_commands

-- get root page
select allocated_page_file_id, allocated_page_page_id, next_page_page_id, previous_page_page_id, page_level 
from sys.dm_db_database_page_allocations(db_id(),object_id('MSrepl_transactions'),1,null,'DETAILED') 
where page_type_desc is not null and page_type_desc = 'INDEX_PAGE'

DBCC TRACEON(3604)
DBCC PAGE (distribution, 1, 72305, 3);
DBCC TRACEOFF(3604)

The last page for the publisher_database_id = 3 range is 72702 and the first page for the publisher_database_id = 4 range is 72629.

To simulate a long duration we can execute the distribution cleanup proc with an open transaction

use distribution
begin tran
EXEC dbo.sp_MSdistribution_cleanup @min_distretention = 0, @max_distretention = 1

Removed 5999 replicated transactions consisting of 5999 statements in 1 seconds (11998 rows/sec).

The cleanup job removed the 5,999 rows we added 1 hour ago for publisher_database_id = 4 and held an X lock on page 72702 that contains the oldest rows for publisher_database_id = 4. We can see the locks using this query

select * from sys.dm_tran_locks where request_session_id = 68 and request_mode = 'X'

In another session, we can execute the following script to add new rows to publisher_database_id = 3 (pub1)

use pub1
insert test1(b,c)
values (getdate(),replicate('x',200))
go 

The log reader agent for publisher_database_id = 3 is blocked by the delete of publisher_database_id = 4, as shown in the spWhoIsActive output, because page 72702 also contains the newest rows for publisher_database_id = 3

Workaround

We can avoid deleting N-1 rows by "delete TOP N" and prevent it from reading million of rows, if we modify the delete loop to iterate a multiple of N on the sp_MSdelete_publisherdb_trans stored procedure.

Code snipped for the MSrepl_commands table

select @max = count(*)/2000 from MSrepl_commands with (INDEX(ucMSrepl_commands), nolock) where
 publisher_database_id = @publisher_database_id and
 xact_seqno <= @max_xact_seqno and
 (type & ~@snapshot_bit) not in (@directory_type, @alt_directory_type) and
 (type & ~@replpost_bit) <> @scriptexec_type
 OPTION (MAXDOP 4)

WHILE @i <= @max
BEGIN

 DELETE TOP(2000) MSrepl_commands WITH (PAGLOCK) from MSrepl_commands with (INDEX(ucMSrepl_commands)) where
  publisher_database_id = @publisher_database_id and
  xact_seqno <= @max_xact_seqno and
  (type & ~@snapshot_bit) not in (@directory_type, @alt_directory_type) and
  (type & ~@replpost_bit) <> @scriptexec_type
  OPTION (MAXDOP 1)
  
 select @row_count = @@rowcount
 -- Update output parameter
 select @num_commands = @num_commands + @row_count
    
 set @i=@i+1
END

Code snipped for the MSrepl_transactions table

select @max = count(*)/5000 from MSrepl_transactions with (INDEX(ucMSrepl_transactions), nolock) where
 publisher_database_id = @publisher_database_id and
 xact_seqno <= @max_xact_seqno and
 xact_seqno <> @last_xact_seqno and
 xact_seqno <> @last_log_xact_seqno
 OPTION (MAXDOP 4)

WHILE @i <= @max
BEGIN
 exec dbo.sp_MSdelete_dodelete @publisher_database_id, 
  @max_xact_seqno, 
  @last_xact_seqno, 
  @last_log_xact_seqno,
  @has_immediate_sync


 select @row_count = @@rowcount

 -- Update output parameter
 select @num_transactions = @num_transactions + @row_count
   
 set @i=@i+1
END

Note that Microsoft doesn't support modifying the system stored procedures, so test it at your own risk

The Power of Window Functions

Window functions are the most efficient way to calculate certain aggregates such as running totals.

For example, we could use the CROSS APPLY operator to calculate the running total, as shown below, using the sample database Wide World Importers

 
SELECT t1.CustomerID, t1.InvoiceID, t1.TransactionAmount
,c.RunningTotali
FROM [WideWorldImporters].[Sales].[CustomerTransactions] t1
CROSS APPLY(
SELECT SUM(t2.TransactionAmount) RunningTotal
FROM [WideWorldImporters].[Sales].[CustomerTransactions] t2
WHERE t2.InvoiceID is not null
AND t2.InvoiceID <= t1.InvoiceID
AND t1.CustomerID = t2.CustomerID
) c
WHERE t1.InvoiceID is not null
ORDER BY t1.CustomerID, t1.InvoiceID

We could refactor this query to use window functions, as shown below

 
SELECT t1.CustomerID, t1.InvoiceID, t1.TransactionAmount,
SUM(t1.TransactionAmount) OVER(PARTITION BY t1.CustomerID
ORDER BY t1.InvoiceID
ROWS BETWEEN UNBOUNDED PRECEDING
AND CURRENT ROW) RunningTotal
FROM [WideWorldImporters].[Sales].[CustomerTransactions] t1
WHERE t1.InvoiceID is not null
ORDER BY t1.CustomerID, t1.InvoiceID

Both queries will get the same result

However, the performance difference is abysmal

As shown above, the CROSS APPLY query (first statement) takes about 5 min and 2 million reads, while the window function (second statement) takes 264 milliseconds and a thousand reads to complete

Enjoy the power.

Querying the Lock Acquired Extended Event

In this post, I will show how to query the lock acquired extended event that I used in the previous post. This query summarizes the data by aggregating the count of locks of the same type but preserving the sequence in which they appeared. For this purpose, I used the SQL 2012 windowing function LAG to solve the “island” problem as described by Itzik Ben-Gan in his T-SQL Querying book.

I used the same sample data of the previous post. Next I used the following extend event filtered by the session id I used to run the delete query, as shown below.

 
CREATE EVENT SESSION [lock_acquired] ON SERVER 
ADD EVENT sqlserver.lock_acquired(SET collect_resource_description=(1)
    ACTION(package0.callstack,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_stack)
    WHERE ([package0].[equal_uint64]([sqlserver].[session_id],(91))))
ADD TARGET package0.event_file(SET filename=N'c:\temp\lock_acquired')
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON,STARTUP_STATE=OFF)
GO

alter event session [lock_acquired]
on server
state = start;

delete top (1000) child_table
from child_table c
left join parent_table p
on c.parent_id = p.parent_id
where p.parent_id is null

alter event session [lock_acquired]
on server
state = stop;

Then you can run the following query to get the locks acquired

with a as(
SELECT
t.c.value ('@name', 'nvarchar(50)') AS event_name
,t.c.value ('@timestamp', 'datetime2') AS event_time
,t.c.value ('(data[@name="associated_object_id"]/value)[1]', 'numeric(20)') AS associated_object_id
,t.c.value ('(data[@name="resource_0"]/value)[1]', 'bigint') AS resource_0
,t.c.value ('(data[@name="resource_1"]/value)[1]', 'bigint') AS resource_1
,t.c.value ('(data[@name="resource_2"]/value)[1]', 'bigint') AS resource_3
,t.c.value ('(data[@name="mode"]/text)[1]', 'varchar(50)') AS mode
,t.c.value ('(data[@name="resource_type"]/text)[1]', 'varchar(50)') AS resource_type
,t.c.value ('(data[@name="database_id"]/value)[1]', 'int') AS database_id
,t.c.value ('(data[@name="object_id"]/value)[1]', 'int') AS object_id
,t.c.value ('(action[@name="attach_activity_id"]/value)[1]', 'varchar(200)') AS attach_activity_id
FROM (
SELECT
    CAST(event_data AS XML) AS event_xml
 FROM sys.fn_xe_file_target_read_file
 (
 'C:\temp\lock_acquired_0_131015242967150000.xel'
 , null
 , null
 , null
)) target_read_file
CROSS APPLY event_xml.nodes ('//event') AS t (c)
where t.c.value ('@name', 'nvarchar(50)') = 'lock_acquired'
and t.c.value ('(data[@name="associated_object_id"]/value)[1]', 'numeric(20)') > 0
and t.c.value ('(data[@name="database_id"]/value)[1]', 'int') <> 2
) 
select
event_time
,object_name(isnull(p.object_id,a.object_id),a.database_id) object_name
,resource_type
,mode
,count(*) count
into #temp
from a
left join sys.partitions p
on a.associated_object_id = p.hobt_id
group by
event_time
,object_name(isnull(p.object_id,a.object_id),a.database_id)
,resource_type
,mode

select object_name, resource_type, mode, count from #temp

You will notice there are about 200+ lines that may be difficult to read and could be solved by the “island” task that Itzik describes as “Identifying islands means returning the ranges of consecutive values.” Which are shown below. We want the consecutive S locks of the parent table as well as the U locks of the child table aggregated preserving the sequence

The SQL 2012 window function LAG did the trick

 
with a as(
select * 
,row_number() over(
order by
event_time
,object_name
,resource_type
,mode
) row_num
from #temp
), b as(
select *
,case when object_name + resource_type + mode <>
lag(object_name + resource_type + mode) over(
order by
row_num
) 
or
lag(object_name + resource_type + mode) over(
order by
row_num
) is null
then 1
else 0
end grp1
from a
), c as(
select *
,sum(grp1) over(
order by row_num
) grp2
from b
)
select 
object_name
,resource_type
,mode
,sum(count) count
from c
group by
grp2
,object_name
,resource_type
,mode
order by
grp2
,object_name
,resource_type
,mode

Lock Escalation and Outer Joins

A common work around to avoid lock escalation is to limit the number of rows per transaction, for example deleting 1,000 rows at a time. However, if a delete is based on an outer join, for example a left join, and the left table is large enough that will require more than 5,000 page locks to read it, the Database Engine will escalate those page locks to table lock regardless of how many rows are deleted.

I can reproduce the issue by running the below queries that populate a parent table with 20,000 values and a child table with 200,000 values.

 
create table parent_table(
parent_id int identity primary key
,parent_col char(255) not null
)

insert parent_table(parent_col)
values('a')
go 20000

create table child_table(
child_id int identity primary key
,parent_id int not null
,child_col char(255) not null
)

insert child_table(parent_id, child_col)
select parent_id, parent_col
from parent_table
go 10

Then delete from the child table rows that don’t have a match in the parent table using a left outer join. In this example it won't find any orphans so it won't delete any row.

 
delete top (1000) child_table
from child_table c
left join parent_table p
on c.parent_id = p.parent_id
where p.parent_id is null

I used the lock acquired event to show what locks were acquired (I will explain the extended events I used in the next post). You will see that due to the left outer join logic the query has to scan all the rows in the child table using an Update (U) lock, and it eventually escalates to Exclusive (X) table lock, blocking any subsequent query on the child table for the duration of the transaction.

A work around is to use a temp table as an intermediate step to find the matching child id

 
select c.child_id
into #temp
from child_table c
left join parent_table p
on c.parent_id = p.parent_id
where p.parent_id is null

delete top (1000) child_table
from child_table c
join #temp t
on c.child_id = t.child_id

Now you will see on the child table an Intend Shared (IS) table lock on the select into portion, and an Intend Exclusive (IX) table lock on the delete section, instead of X table lock in the previous query, allowing more concurrency on the child table.