How It Works: How is SQL Server Error 833, 15 Sec I/O Detected

 

I was approached to revisit the details of how Error Message 833 is detected and reported.

SQL Server has encountered %d occurrence(s) of I/O requests taking longer than %d seconds to complete on file [%ls] in database [%ls] (%d). The OS file handle is 0x%p. The offset of the latest long I/O is: %#016I64x.

Older versions of SQL Server leveraged the Lazy Writer and I/O completion callback routines to record vs report the error condition.  Newer versions of SQL Server have refined the detection, now the logic is included as part of the Scheduler Monitor.  All the I/O requests contain a start time (invariant RDTSC ticks), the OVERLAPPED structure and additional tracking information. The I/O tracking structures are all allocated out of the same memory so we don’t deadlock trying to allocate them from a memory manager/object that has to do I/O when low on memory.

When Scheduler Monitor does its checks (5 sec intervals) we walk over the in-motion, I/O entries and check the OVERLAPPED status to see if the I/O request is still pending at the kernel. If (Overlapped->Internal), decimal value, is 259 the I/O is pending at kernel level and when the elapsed time becomes greater than 15 seconds we record the slow I/O condition.

The process is a bit more involved, using the I/O request dispenser and a check limit of 1024, I/O requests in which Scheduler Monitor will traverse in a single check, but basically SQL Server runs the I/O tracking list and checks the result of HasOverlappedIoCompleted. If the OVERLAPPED->Internal value is no longer 259 the issue is an SOS scheduling issue in processing the I/O and we don’t record it as a slow I/O. The sys.dm_os_pending_io_requests DMV shows the IsPending column which is just the outcome of HasOverlappedIoCompleted which is used for the column output so you can see the I/O state. There is no timer per I/O involved from Windows as Scheduler Monitor acts as the monitor.

SQL Server maintains a 5-minute reporting interval, per file to prevent flood of error log as the target to when we will write the warning to the error log. XEvent could be a better target when troubleshooting the problem (XeSqlPkg::long_io_detected fires at the time of recording in most instances.)

To recap, Scheduler Monitor does the work to look at the I/O state and when pending and greater than 15 seconds the 833 logic is invoked.

Bob Dorr - Principal Software Engineer SQL Server

Comments

• Anonymous
  September 02, 2016
  I <3 this blog.
• Anonymous
  September 13, 2016
  Bob, how does this work with modern SANs? I've gotten these messages when we're doing a ton of IO, but I've suspected that sometimes the SAN can accept 1,000 read requests at like ten microseconds each, and then works for 30 seconds to fulfill them all. We might then get these "15 second" warnings but they're bogus, they are confusing queue time with *response time. Any light you can shine on this would be very welcome.
  • Anonymous
    September 14, 2016
    The warnings are not incorrect. SQL might post a bunch of I/O but each I/O is limited in size. Say SQL does read-ahead and posts 100, 512K I/Os. We then wait on the first I/O request and not all I/O requests to complete. So if the SAN does not return the 1st request until 100 requests are completed then I would talk with the SAN vendor. As soon as the I/O request is done it should be marked as completed at the OS/Hardware level. If not getting completed the SAN is simply not responding to an individual I/O cleanly.
• Anonymous
  June 22, 2017
  What about 833s when Commserve is taking an image backup of the VM?
• Anonymous
  November 30, 2017
  The I/O tracking structures are all allocated out of the same memory so we don’t deadlock trying to allocate them from a memory manager/object that has to do I/O when low on memory.It means memory doesn't come from Buffer pool. Am I right Sir pls