SQL Alwayson availabity group latency

Question

We have sql server 2014 alwayson availability group set up for a database. Synchronous-commit availability mode is used. We ran a few PAL (Performance Analyzer Log) reports to obtain performance data on the primary replica and they showed IO alerts where read and writes were >25ms. The IO alerts occurred for both logical and physical IOs and on drives C:, F: (that has db files) and L: (that has transaction logs). I ran this statement:

SELECT 
    wait_type, waiting_tasks_count, wait_time_ms,
    wait_time_ms/waiting_tasks_count as 'time_per_wait'
FROM 
    sys.dm_os_wait_stats 
WHERE 
    waiting_tasks_count > 0
    and wait_type = 'HADR_SYNC_COMMIT';

and got 12ms for the time_per_wait value. This means the latency between the primary and secondary replicas were 12 ms.

My question: does the IO response time reported by PAL include this 12ms latency between the primary and the secondary replicas?

Thanks

Answer 1

According to PSS that wait type is the time it takes for the primary to receive a notification that the log block has been written on the destination (though not replayed), and after this the wait type changes to WRITELOG and the log block gets written locally.

Logically then any disk waits to write the block remotely must be included in that HADR_SYNC_COMMIT time.

Perhaps if you run PAL on your secondary you will see that it has lower disk latency and so can complete the writes faster. It would be interesting for you to look and see.

Incidentally the MSSQL Tiger Team have a video and demo XE script and Power BI sample that gathers AG sync information and displays it in graphs; if you're interested in exploring that you could give it a try.

Answer 2

select wait_type, waiting_tasks_count, wait_time_ms, wait_time_ms/waiting_tasks_count as 'time_per_wait' from sys.dm_os_wait_stats where waiting_tasks_count >0 and wait_type = 'HADR_SYNC_COMMIT';

and got 12ms for the time_per_wait value. This means the latency between the primary and secondary replicas were 12 ms.

This is not the proper way of measuring synchronous commit overhead. This means we "waited" on synchronous commits for something but can't be resolved to "My overhead is 12 ms".

Well then, why? This is because in SQL Server when "something" hits a waiting point it adds to the overall wait time. This works out well when only 1 "thing" is waiting... but what if we had 2 things waiting, each on the same operation to complete... then we have 2*wait_time even though the wait time wasn't doubled.

The proper way to measure this is by using either the perfmon counters under SQLServer:Database Replica - Transaction Delay and Mirrored Write Transactions/Sec.

Transaction Delay is how much time, total in milliseconds, it took for all of the mirrored writes to complete in that interval (1 second).

Mirrored Write Transactions/Sec is how many synchronous transactions we sent to the secondary per second.

If we divide Transaction Delay by Mirrored Writes we get ms per transaction. That's the mostly accurate (without extended events in the debug channel) way of getting the overhead per transaction.

My question: does the IO response time reported by PAL include this 12ms latency between the primary and the secondary replicas?

The answer to this is a solid, "Yes". We need to write the log blocks to disk, that's when we can arguably be safe in our assumption that the secondary has hardened the data. It isn't redone yet but it is on disk in the log.

If it takes, on average, 25 ms to write to disk then that will be included in our overhead time. This is because we need to harden that data onto disk.

Why might this not synch up? Why wouldn't the overhead per transaction be 25ms + network latency? Not every IO will take 25 ms, that's the average. Some may be faster, some may be slower. Some may be caused by system processes or cache fullness. Using the method I gave above will give you mostly real-time information.