Skip to main content
3 of 9
added 12 characters in body
Mark S. Rasmussen
  • 1.5k
  • 1
  • 14
  • 20

I/O requests taking longer than 15 seconds

Usually our weekly full backups finish in about 35 minutes, with daily diff backups finishing in ~5 minutes. Since tuesday the dailies have taken almost 4 hours to complete, way more than should be required. Coincidentally, this started happening right after we got a new SAN/disk config.

Note that the server is running in production and we have no overall issues, it's running smoothly - except for the IO issue that's primarily manifested itself in the backup performance.

Looking at dm_exec_requests during the backup, the backup is constantly waiting on ASYNC_IO_COMPLETION. Aha, so we have disk contention!

However, neither the MDF (logs are stored on local disk) nor backup drive have any activity (IOPS ~= 0 - we have plenty of memory). Disk queue length ~= 0 as well. CPU hovers around 2-3%, no issue there either.

The SAN is a Dell MD3220i, the LUN consisting of 6x10k SAS drives. The server is connected to the SAN through two physical paths, each going through a separate switch with redundant connections to the SAN - a total of four paths, two of them being active at any time. I can verify that both connections are active through task manager - splitting the load perfectly evenly. Both connections are running 1G full duplex.

We used to use jumbo frames, but I've disabled them to rule out any issues here - no change. We have another server (same OS+config, 2008 R2) that is connected to other LUNs, and it shows no issues. It is however not running SQL Server, but just sharing CIFS on top of them. However, one of its LUNs preferred path is on the same SAN controller as the troublesome LUNs - so I've ruled that out as well.

Running a couple of SQLIO tests (10G test file) seems to indicate that IO is decent, despite the issues:

sqlio -kR -t8 -o8 -s30 -frandom -b8 -BN -LS -Fparam.txt
IOs/sec:  3582.20
MBs/sec:    27.98
Min_Latency(ms): 0
Avg_Latency(ms): 3
Max_Latency(ms): 98
histogram:
ms: 0  1  2  3  4  5  6  7  8  9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24+
%: 45  9  5  4  4  4  4  4  4  3  2  2  1  1  1  1  1  1  1  0  0  0  0  0  2

sqlio -kW -t8 -o8 -s30 -frandom -b8 -BN -LS -Fparam.txt
IOs/sec:  4742.16
MBs/sec:    37.04
Min_Latency(ms): 0
Avg_Latency(ms): 2
Max_Latency(ms): 880
histogram:
ms: 0  1  2  3  4  5  6  7  8  9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24+
%: 46 33  2  2  2  2  2  2  2  1  1  1  1  0  0  0  0  0  0  0  0  0  0  0  1

sqlio -kR -t8 -o8 -s30 -fsequential -b64 -BN -LS -Fparam.txt
IOs/sec:  1824.60
MBs/sec:   114.03
Min_Latency(ms): 0
Avg_Latency(ms): 8
Max_Latency(ms): 421
histogram:
ms: 0  1  2  3  4  5  6  7  8  9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24+
%:  1  3 14  4 14 43  4  2  1  1  1  1  1  1  0  0  0  0  0  0  0  0  0  0  6

sqlio -kW -t8 -o8 -s30 -fsequential -b64 -BN -LS -Fparam.txt
IOs/sec:  3238.88
MBs/sec:   202.43
Min_Latency(ms): 1
Avg_Latency(ms): 4
Max_Latency(ms): 62
histogram:
ms: 0  1  2  3  4  5  6  7  8  9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24+
%:  0  0  0  9 51 31  6  1  0  0  0  0  0  0  0  0  0  0  0  0  0  0  0  0  0

I realize that these aren't exhaustive tests in any way, but they do make me comfortable in knowing that it isn't complete rubbish. Note that the higher write performance is caused by the two active MPIO paths, whereas reading will only use one of them.

Checking the Application event log reveals events like these scattered around:

SQL Server has encountered 2 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [J:\XXX.mdf] in database [XXX] (150).  The OS file handle is 0x0000000000003294.  The offset of the latest long I/O is: 0x00000033da0000

They're not constant, but they do happen regularly (a couple per hour, more during backups). Alongside that event, the System event log will post these:

Initiator sent a task management command to reset the target. The target name is given in the dump data.
Target did not respond in time for a SCSI request. The CDB is given in the dump data.

These also occur on the non-problematic CIFS server running on the same SAN/Controller, and from my Googling they seem to be non-critical.

Note that all servers use the same NICs - Broadcom 5709Cs with up-to-date drivers. The servers themselves are Dell R610's.

I'm not sure what to check for next. Any suggestions?

Mark S. Rasmussen
  • 1.5k
  • 1
  • 14
  • 20