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.