Difference between avg Disk sec/write and io_stall_write_ms

Question

We have a SQL Server 2016 SP2 Enterprise with latest CU with the database files spread out over different disks.
So we have data,log, tempdb and system db's have each their own drive. Date and log only contain one file.
Those drives each has their own LUN on a All-Flash SAN.

To monitor the latency I capture sys.dm_io_virtual_file_stats every 15 minutes and then calculate the latency using the previous snapshot.

For the write latency I'm using following calculation:

(io_stall_write_ms - lag (io_stall_write_ms,1,0) over (order by checkdate))/(num_of_writes - lag (num_of_writes,1,0) over (order by checkdate)) write_latency 

I'm getting an average write latency of 10ms but when I'm starting perfmon (with duration set to 900 seconds) and monitor the avg. Disk sec/Write in the same period for the same drive I'm only getting an average write latency of 3 ms.

I'm also capturing the wait stats for the same period, when I look at PAGEIOLATCH_EX waits and calculates how long every wait took, I'm also getting a value of approx 3ms.

I thought io_stall_write_ms represented the same as avg. Disk sec/Write or am I missing something?
Can somebody explain this behavior?

Answer 1

I think your conclusion that these two numbers should match up is fair. That measurement of write latency from sys.dm_io_virtual_file_stats should provide similar numbers to the "Logical Disk" ➡ "Avg. Disk sec/Write" Perfmon counter.

Make sure that you are comparing "apples to apples" as much as possible. The default for that Perfmon counter is to show you latency across all disks, so make sure you've selected the disk you're interested in (not "Total"):

Similarly, on the SQL Server DMV side, make sure you're only aggregating and comparing data for files on that same disk. The sys.dm_io_virtual_file_stats is giving you data per file, which could be across multiple disks.

It could just be the differences in sample rates between the different ways of measuring that are throwing things off. For instance, you're getting the DMV data every 15 minutes. But presumably you were viewing the live output of the default Perfmon, which will show you the average over 100 seconds. There might just be outliers in the 15 minute interval that lead to the average being higher for the DMV than what you're seeing in Perfmon. To try and rule this out, you could (at least temporarily) sample virtual file stats more frequently to see if the numbers match up better.

I expect, based on the lower latency-related values you see in Perfmon and wait stats, that you're not actively having disk latency issues, and you're just curious about the difference measurements you're getting from the different tools.

If you are having issues, you might be in for a deeper dive into "what's getting between SQL Server and the disk writes." Top Microsoft Man Sean Gallardy talks about that pretty in depth here: Slow checkpoint and 15 second I/O warnings on flash storage

Answer 2

After reading the post of Sean Gallardy I setup StorPort tracing using Perfmon. How to configure the tracing you find here and used StorPort-Trace-Reader to analyze the results.
The results showed that there was indeed some latency.

Next I used Windows Performance Recorder to trace the "Minifilter I/O activity". Using the Windows Performance Analyzer I discovered the virusscanner was causing the troubles, even though exclusions where made, a lot of time was spent in those minifilters.
After uninstalling the virusscanner the problem was solved. Now we are searching why the virusscanner was causing the issue.