Solicitações de E/S demorando mais de 15 segundos

Normalmente, nossos backups semanais completos terminam em cerca de 35 minutos, com os backups diários de diferenças terminando em aproximadamente 5 minutos. Desde terça-feira, os diários levaram quase 4 horas para serem concluídos, muito mais do que deveria ser necessário. Coincidentemente, isso começou a acontecer logo após obtermos uma nova configuração de SAN/disco.

Observe que o servidor está sendo executado em produção e não temos problemas gerais, está funcionando sem problemas - exceto pelo problema de E/S que se manifesta principalmente no desempenho do backup.

Olhando para dm_exec_requests durante o backup, o backup está constantemente esperando em ASYNC_IO_COMPLETION. Aha, então temos contenção de disco!

No entanto, nem o MDF (os logs são armazenados no disco local) nem a unidade de backup têm nenhuma atividade (IOPS ~= 0 - temos muita memória). Comprimento da fila de disco ~= 0 também. A CPU gira em torno de 2-3%, também não há problema.

A SAN é um Dell MD3220i, o LUN consiste em unidades SAS de 6x10k. O servidor é conectado à SAN por meio de dois caminhos físicos, cada um passando por um switch separado com conexões redundantes à SAN - um total de quatro caminhos, dois deles ativos a qualquer momento. Posso verificar se ambas as conexões estão ativas por meio do gerenciador de tarefas - dividindo a carga de maneira perfeitamente uniforme. Ambas as conexões estão executando 1G full duplex.

Costumávamos usar quadros jumbo, mas eu os desabilitei para descartar quaisquer problemas aqui - sem mudança. Temos outro servidor (mesmo OS+config, 2008 R2) que está conectado a outros LUNs e não apresenta problemas. No entanto, não está executando o SQL Server, mas apenas compartilhando o CIFS sobre eles. No entanto, um de seus caminhos preferidos de LUNs está no mesmo controlador SAN que os LUNs problemáticos - então eu também descartei isso.

A execução de alguns testes SQLIO (arquivo de teste 10G) parece indicar que o IO é decente, apesar dos problemas:

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

Eu percebo que esses testes não são exaustivos de forma alguma, mas eles me deixam confortável em saber que não é uma porcaria completa. Observe que o maior desempenho de gravação é causado pelos dois caminhos MPIO ativos, enquanto a leitura usará apenas um deles.

A verificação do log de eventos do aplicativo revela eventos como estes espalhados:

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

Eles não são constantes, mas acontecem regularmente (alguns por hora, mais durante os backups). Juntamente com esse evento, o log de eventos do sistema postará:

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.

Isso também ocorre no servidor CIFS não problemático em execução no mesmo SAN/controlador e, pelo meu Google, eles parecem não ser críticos.

Observe que todos os servidores usam as mesmas NICs - Broadcom 5709Cs com drivers atualizados. Os próprios servidores são Dell R610.

Não tenho certeza do que verificar a seguir. Alguma sugestão?

Update - Perfmon em execução
, tentei gravar o Avg. Contadores de desempenho de disco/leitura e gravação durante a execução de um backup. O backup começa incrivelmente e basicamente para em 50%, rastejando lentamente em direção a 100%, mas levando 20x o tempo que deveria.

Mostra os dois caminhos SAN sendo utilizados e, em seguida, descartados.

O backup foi iniciado por volta das 15:38:50 - observe que tudo parece bom e, em seguida, há uma série de picos. Não estou preocupado com as gravações, apenas as leituras parecem travar.

Observe muito pouca ação liga/desliga, embora um desempenho incrível no final.

Observe um máximo de 12 segundos, embora a média geral seja boa.

Atualização - Fazendo backup para o dispositivo NUL
Para isolar problemas de leitura e simplificar as coisas, executei o seguinte:

BACKUP DATABASE XXX TO DISK = 'NUL'

Os resultados foram exatamente os mesmos - começa com uma leitura intermitente e depois para, retomando as operações de vez em quando:

Update - IO stalls
Executei a consulta dm_io_virtual_file_stats do livro de Jonathan Kehayias e Ted Kruegers ( página 29), conforme recomendado por Shawn. Olhando para os 25 principais arquivos (um arquivo de dados cada - todos os resultados sendo arquivos de dados), parece que as leituras são piores do que as gravações - talvez porque as gravações vão diretamente para o cache SAN, enquanto as leituras frias precisam atingir o disco - apenas um palpite .

Atualização - Estatísticas de espera
Fiz três testes para reunir algumas estatísticas de espera. As estatísticas de espera são consultadas usando o script Glenn Berry/Paul Randals . E só para confirmar - os backups não estão sendo feitos em fita, mas em um iSCSI LUN. Os resultados são semelhantes se feitos no disco local, com resultados semelhantes aos do backup NUL.

Estatísticas limpas. Funcionou por 10 minutos, carga normal:

Cleared stats. Ran for 10 minutes, normal load + normal backup running (didn't complete):

Cleared stats. Ran for 10 minutes, normal load + NUL backup running (didn't complete):

Update - Wtf, Broadcom?
Based on Mark Storey-Smiths suggestions and Kyle Brandts previous experiences with Broadcom NICs, I decided to do some experimentation. As we've got multiple active paths, I could relatively easily change the configuration of the NICs one by one without causing any outages.

Disabling TOE and Large Send Offload yielded a near perfect run:

Processed 1064672 pages for database 'XXX', file 'XXX' on file 1.
Processed 21 pages for database 'XXX', file 'XXX' on file 1.
BACKUP DATABASE successfully processed 1064693 pages in 58.533 seconds (142.106 MB/sec).

So which is the culprit, TOE or LSO? TOE enabled, LSO disabled:

Didn't finish the backup as it took forever - just as the original problem!

TOE disabled, LSO enabled - looking good:

Processed 1064680 pages for database 'XXX', file 'XXX' on file 1.
Processed 29 pages for database 'XXX', file 'XXX' on file 1.
BACKUP DATABASE successfully processed 1064709 pages in 59.073 seconds (140.809 MB/sec).

And as a control, I disabled both TOE and LSO to confirm the issue was gone:

Processed 1064720 pages for database 'XXX', file 'XXX' on file 1.
Processed 13 pages for database 'XXX', file 'XXX' on file 1.
BACKUP DATABASE successfully processed 1064733 pages in 60.675 seconds (137.094 MB/sec).

In conclusion it seems the enabled Broadcom NICs TCP Offload Engine caused the problems. As soon as TOE was disabled, everything worked like a charm. Guess I won't be ordering any more Broadcom NICs going forward.

Update - Down goes the CIFS server
Today the identical and functioning CIFS server started exhibiting IO requests hanging. This server wasn't running SQL Server, just plain Windows Web Server 2008 R2 serving shares over CIFS. As soon as I disabled TOE on it as well, everything was back to running smooth.

Just confirms I won't ever be using TOE on Broadcom NICs again, if I can't avoid the Broadcom NICs at all, that is.