SQL server is reporting long disk response and large disk queue lengths
Applies to
- Microsoft SQL Server
- ONTAP 9
- E-Series
Issue
- In the Windows Resource Monitor, under "Disk Activity" we can see disks reporting high "Response Time" and can also see high "Disk Queue Length" under "Storage" section.
- SQL Agent Jobs (batch jobs) are taking longer time than what is expected and then getting failed
- SQL performance issues may be seen overall, and Microsoft may suggest to check storage
- SQL Server errorlog is displaying large number of FlushCache messages indicating IO issues:
2021-02-09 10:21:48.590 spid21s FlushCache: cleaned up 19485 bufs with 15249 writes in 488889 ms (avoided 987 new dirty bufs) for db 6:0
2021-02-09 10:21:48.590 spid21s average writes per second: 31.19 writes/sec
average throughput: 0.31 MB/sec, I/O saturation: 19959, context switches 104381
2021-02-09 10:21:48.590 spid21s last target outstanding: 13100, avgWriteLatency 2
2021-02-09 10:29:58.510 spid21s FlushCache: cleaned up 2754 bufs with 2266 writes in 171682 ms (avoided 6298 new dirty bufs) for db 6:0
2021-02-09 10:29:58.510 spid21s average writes per second: 13.20 writes/sec
average throughput: 0.12 MB/sec, I/O saturation: 6978, context switches 18314
2021-02-09 10:29:58.520 spid21s last target outstanding: 2, avgWriteLatency 113
2021-02-09 10:33:28.300 spid21s FlushCache: cleaned up 4360 bufs with 1554 writes in 148717 ms (avoided 1869 new dirty bufs) for db 6:0
2021-02-09 10:33:28.300 spid21s average writes per second: 10.45 writes/sec
average throughput: 0.23 MB/sec, I/O saturation: 5536, context switches 15283
2021-02-09 10:33:28.300 spid21s last target outstanding: 2, avgWriteLatency 48
2021-02-09 10:37:56.710 spid21s FlushCache: cleaned up 3223 bufs with 1001 writes in 97386 ms (avoided 273 new dirty bufs) for db 6:0
2021-02-09 10:37:56.710 spid21s average writes per second: 10.28 writes/sec
average throughput: 0.26 MB/sec, I/O saturation: 3598, context switches 9648
2021-02-09 10:37:56.710 spid21s last target outstanding: 8, avgWriteLatency 199
2021-02-09 10:39:24.690 spid21s FlushCache: cleaned up 1689 bufs with 475 writes in 77464 ms (avoided 308 new dirty bufs) for db 13:0
2021-02-09 10:39:24.690 spid21s average writes per second: 6.13 writes/sec
average throughput: 0.17 MB/sec, I/O saturation: 2593, context switches 7651
2021-02-09 10:39:24.690 spid21s last target outstanding: 2, avgWriteLatency 247