I/O requests taking longer than 15 seconds to complete on file


What does the “I/O request” error below represent?


 


2008-04-21 13:26:42.480 spid364      Microsoft SQL Server 2005 – 9.00.3177.00 (Intel X86)


2008-04-22 16:30:02.140 spid6s       SQL Server has encountered 2 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [F:\sql data files\xxx.MDF] in database [xxx] (5). 


2008-04-22 16:32:08.780 spid6s       SQL Server has encountered 2 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [H:\sql data files\xxx_data_4.NDF] in database [xxx] (5). 


 


Research and Findings


———————————


These errors may occur as result of “CPU Drift” and can be ignored and disabled, howerver, first verify both SQL DMV sys.dm_io_pending_io_requests and Windows Performance counters don’t indicate any IO delays.


 


On computers with multiple CPUs, the CPUs are designed to “sleep” during periods of low workload.  When CPUs sleep, SQL may not accurately determine CPUs overall workload and incorrectly report this as IO WARNING shown above, however, this does not represent an actual CPU performance problem.


 


To confirm if the CPUs entered low-power state, SQL Server Escalation Services created RDTSC (Read Time Stamp Counter) utility to report total CPU sleep time.  The report confirmed the CPUs were sleeping up to 24 seconds.  This would be enough for SQL Server to incorrectly report this a slow IO.  Both AMD’s and INTEL’s web sites describe the ability for CPUs to sleep.


 


RDTSCTest.exe [-md|-mt]


      -md   Detailed output (default)


      -mt   CPU speeds in table format


 


— Current CPU Speeds —


Runtime              CPU  ExpectedMHz ActualMHz RDTSCTicks           DriftMS         


——————– —- ———– ——— ——————– —————-


2008-04-22 17:53:36     0        3502      3503 0x0001564772F87FA72    16123.4


2008-04-22 17:53:36     8        3502      3506 0x00015647D8B7AE21D    23922.5


2008-04-22 17:53:36    16        3502      3507 0x00015647B5FEB4A39    21260.9


 


For more information on  RDTSC can be found at


http://blogs.msdn.com/psssql/archive/2007/08/19/sql-server-2005-rdtsc-truths-and-myths-discussed.aspx


 


Starting with SQL 2005 SP2 we’ve included two trace flags to disable the reporting of CPU Drift errors in the SQL Server errorlog. 


 


Disable this error using Trace Flag 8033


The time stamp counter of CPU on scheduler id 1 is not synchronized with other CPUs.


 


Disable this error using Trace Flag 830


SQL Server has encountered 2 occurrence(s) of I/O requests taking longer than 15 seconds to complete


 


Comments (2)

  1. Ricardo Vaghi says:

    A server´s firmware update was enough in my case

  2. Nick Duckstein says:

    Would this be something we would be likely to encounter in a VM environment?

    That’s where we are experiencing it.

    Am I correct with the following assumptions:

    1. If we don’t see a lot of pending requests in sys.dm_io_pending_io_requests that we can disable these errors.

    2. If there are a lot of pending io requests, then we have a potential disk subsystem/IO issue to investigate.

    ————REPLY——

    If the IO warning occur rarely, often just one here or there, they can be ignored.  If you see a BLOCK of IO warnings, also take a look at Windows Perfmon disk IO counters.  Avg Read/Write /SEC good counters for overall IO performance.  Read/Write should be < 15ms  (.0015).  If you see sustained > .0030 (30ms), then SQL saturating the IO (large query), or problem in drivers/firmware in IO subsystem.

Skip to main content