SQL: O que está retardando os INSERTs se não a CPU ou o IO?

19

Temos um banco de dados para um produto com muita gravação. Acabamos de comprar uma nova máquina servidor com um SSD para ajudar. Para nossa surpresa, as inserções não foram mais rápidas do que em nossa máquina antiga, com armazenamento muito mais lento. Durante o benchmarking, observamos que a taxa de E / S exibida pelo processo do SQL Server era muito baixa.

Por exemplo, executei o script encontrado nesta página , exceto que adicionei um BEGIN TRAN e COMMIT ao redor do loop. Na melhor das hipóteses, eu pude ver o uso do disco atingir 7 Mb / s, enquanto a CPU mal tocou em 5%. O servidor possui 64 Gb instalados e está usando 10. O tempo total de execução foi de 2 minutos e 15 segundos na primeira chamada, até cerca de 1 minuto nas chamadas subseqüentes. O banco de dados está em recuperação simples e ficou inativo durante o teste. Larguei a mesa entre cada ligação.

Por que um script tão simples é tão lento? O hardware mal está sendo usado. As ferramentas dedicadas de benchmarking de disco e o SQLIO indicam que o SSD funciona corretamente com velocidades acima de 500 Mb / s para leitura e gravação. Entendo que as gravações aleatórias são mais lentas que as sequenciais, mas eu esperaria que uma inserção simples como essa, em uma tabela sem indexação em cluster, fosse muito mais rápida.

Por fim, nosso cenário é muito mais complexo, mas sinto que preciso entender um caso simples primeiro. Em poucas palavras, nosso aplicativo exclui dados antigos, depois usa SqlBulkCopy para copiar novos dados para tabelas temporárias, realiza alguma filtragem e, finalmente, usa MERGE e / ou INSERT INTO, dependendo dos casos para copiar os dados para as tabelas finais.

-> EDIÇÃO 1: segui o procedimento vinculado por Martin Smith e obtive o seguinte resultado:

[Wait Type]  [Wait Count] [Total Wait (ms)] [T. Resource Wait (ms)] [T. Signal Wait (ms)]
NETWORK_IO          5008              46735                 46587        148
LOGBUFFER           901               5994                  5977         17
PAGELATCH_UP        40                866                   865          1
SOS_SCHEDULER_YIELD 53279             219                   121          98
WRITELOG            5                 145                   145          0
PAGEIOLATCH_UP      4                 58                    58           0
LATCH_SH            5                 0                     0            0

Acho estranho que o NETWORK_IO leve a maior parte do tempo, considerando que não há resultado a ser exibido nem dados a serem transferidos para outro lugar além dos arquivos SQL. O tipo NETWORK_IO inclui todas as E / S?

-> EDIÇÃO 2: Criei um disco RAM de 20Gb e montei um banco de dados a partir daí. O melhor tempo que tive no SSD é de 48 anos, com o disco RAM que caiu para 37 segundos. NETWORK_IO ainda é a maior espera. A velocidade máxima de gravação no disco RAM foi de cerca de 250 Mb / s, enquanto é capaz de executar vários gigabytes por segundo. Ainda não estava usando muita CPU, então o que está segurando o SQL?

Djof
fonte
1
Você pode usar o script aqui para capturar estatísticas de espera para um spid específico . Eu acrescentaria SET NOCOUNT ONa isso também.
Martin Smith
3
o NETWORK_IOpoderia ser a 3 milhões "1 row (s) afetada" mensagens sendo enviadas de volta. Você tentou adicionar SET NOCOUNT ONao script?
Martin Smith
Sim, eu adicionei o NOCOUNT.
Djof 21/02/12
2
Estranho. Eu não esperaria muito em termos de atividade de rede. Você excluiu os arquivos antigos de eventos estendidos entre as execuções? O script que os lê usa um curinga EE_WaitStats*.xelpara que os antigos contaminem seus resultados.
Martin Smith
Boa chamada, vou atualizar os resultados amanhã.
Djof 22/02/12

Respostas:

9

Eu sei que é uma pergunta antiga, mas isso ainda pode ajudar os pesquisadores e é um problema que aparece de vez em quando.

A principal razão pela qual você está atingindo um limite de desempenho sem ver nenhum gargalo de recurso é porque atingiu o limite do que é possível processar dentro de um único encadeamento de sessão. O loop não é processado em paralelo, mas todas as inserções são feitas em série.

No meu caso, são necessários 36 segundos para inserir 3 milhões de linhas. Isso significa 36/30000000 = 0,000012 segundos por linha. Isso é bem rápido. No meu sistema, basta levar 0,000012 para executar todas as etapas necessárias.

A única maneira de fazer isso mais rápido é iniciar uma segunda sessão em paralelo.

Se eu iniciar duas sessões em paralelo, ambas fazendo 15 milhões de inserções. Ambos terminam em 18 segundos. Eu poderia escalar mais, mas minha configuração de teste atual está atingindo 95% da CPU em duas sessões paralelas; portanto, fazer 3 distorceria os resultados, pois eu atingia um gargalo de CPU.

Se eu iniciar 2 sessões paralelas, inserindo 3 milhões de linhas, elas terminam em 39 segundos. agora são 6 milhões de linhas em 39 segundos.

Ok, isso ainda nos deixa com a espera do NETWORK_IO aparecendo.

As esperas NETWORK_IO são adicionadas pelo fato de você estar usando eventos estendidos para rastreá-los. No meu caso, a inserção leva 36 segundos (em média). Ao usar a maneira de evento estendido (no link acima no primeiro comentário), é isso que é registrado:

Wait Type             Wait Count  Total Wait Time (ms) Total Resource Wait Time (ms) Total Signal Wait Time (ms)
NETWORK_IO            3455        68808                68802                         6
PAGEIOLATCH_SH        3           64                   64                            0
PAGEIOLATCH_UP        12          58                   58                            0
WRITE_COMPLETION      8           15                   15                            0
WRITELOG              3           9                    9                             0
PAGELATCH_UP          2           4                    4                             0
SOS_SCHEDULER_YIELD   32277       1                    0                             1
IO_COMPLETION         8           0                    0                             0
LATCH_SH              3           0                    0                             0
LOGBUFFER             1           0                    0                             0

Você pode ver que 68 segundos de NETWORK_IO estão registrados. Mas, como o loop de inserção é uma ação thread única que levou 36 segundos, isso não pode ser. (Sim, vários encadeamentos são usados, mas as operações são seriais, nunca em paralelo; portanto, você não pode acumular mais tempo de espera do que a duração total da consulta)

Se eu não usar eventos estendidos, mas apenas as DMVs das estatísticas de espera em uma instância silenciosa (apenas comigo executando a inserção), eu recebo o seguinte:

Wait Type                   Wait Count  Total Wait Time (ms)  Total Resource Wait Time (ms) Signal Resource Wait Time (ms)
SOS_SCHEDULER_YIELD             8873                 0.21                                    0.01                                    0.20
PAGEIOLATCH_UP                  3                    0.02                                    0.02                                    0.00
PREEMPTIVE_OS_AUTHENTICATIONOPS 17                   0.02                                    0.02                                    0.00
PAGEIOLATCH_SH                  1                    0.00                                    0.00                                    0.00

Portanto, o NETWORK_IO que você estava vendo no log de eventos estendidos não estava relacionado ao seu loop de inserção. (Se você não ativar o número, você terá um enorme IO da rede assíncrona, +1 Martin)

No entanto, não sei por que o NETWORK_IO aparece no rastreamento de evento estendido. Certamente, a gravação para um destino de arquivo assíncrono dos eventos acumula ASYNC_NETWORK_IO, mas certamente tudo isso é feito em um SPID diferente do que estamos filtrando. Eu poderia fazer isso como uma nova pergunta)

Edward Dortland
fonte
1
"você está atingindo um limite de desempenho sem ver nenhum gargalo de recursos é porque atingiu o limite do que é possível processar em um único segmento de sessão": você está descrevendo um gargalo de 100% da CPU (em um núcleo). Se não houver gargalo, o sistema será mais rápido, então outra coisa deve estar em jogo.
Remus Rusanu
Sua resposta é muito informativa, Edward. Parece que o paralelismo é a solução para o nosso problema, já estamos trabalhando nisso, embora exija mudanças no layout do banco de dados. Como Remus, no entanto, ainda estou curioso para saber por que a máquina não parecia usar todos os recursos (de um) da CPU ou do disco.
Djof
9

Normalmente você começar olhando sys.dm_exec_requests, especificamente a wait_time, wait_typee wait_resourcepara o seu pedido (s) INSERT. Isso dará uma indicação clara do que está bloqueando o seu INSERT. Os resultados indicarão se há contenção de bloqueio, eventos de crescimento de arquivos, espera de liberação de log, contenção de alocação (manifesta como contenção de trava de página do PFS) etc. etc etc. Depois de medir, atualize sua pergunta. Peço que você pare agora e leia a metodologia de solução de problemas de Esperas e Filas antes de prosseguir.

Remus Rusanu
fonte
3

Eu executei o script de teste na página vinculada no OP com o BEGIN TRAN / COMMIT em volta do loop. Na minha máquina, demorou 1:28 para concluir a primeira vez.

Então eu mudei esses dois comandos para fora do loop:

SELECT @Random = ROUND(((@Upper - @Lower -1) * RAND() + @Lower), 0)
SET @InsertDate = DATEADD(dd, @Random, GETDATE())

Concluiu em 28 segundos depois disso.

Não sei ao certo o que está acontecendo, mas acho que pode haver algum tipo de sono no RAND()código, talvez como parte do algoritmo que eles estão usando para gerar entropia (melhores números aleatórios).

FWIW, SSDs nem sempre são a melhor tecnologia para aplicativos com gravação pesada. Para obter o melhor desempenho, verifique se o log do banco de dados está em uma letra de unidade diferente dos dados do banco de dados, se o arquivo de log é pré-aumentado para o tamanho máximo e nunca trunca o log.

RickNZ
fonte
Obrigado pela sua entrada RickNZ. Não obtive resultados mais rápidos movendo o código para fora do loop. A espera que observei é que, se você executá-lo várias vezes, fica mais rápido, pode ser o que você experimentou. Eu sei que os SSDs não são balas de prata, mas ainda sinto que o desempenho não é o que poderia ser.
Djof
1

Outro DMV que eu uso para identificar a lentidão é sys.dm_os_waiting_tasks . Se sua consulta não exigir muita CPU, você poderá encontrar mais informações sobre as esperas desta DMV.

StanleyJohns
fonte
0

Estou verificando a lista de eventos de espera do sql 2008 e não vejo o NETWORK_IO listado: http://technet.microsoft.com/en-us/library/ms179984(v=sql.100).aspx

Eu pensei que o NETWORK_IO agora estava listado apenas como ASYNC_NETWORK_IO, então eu queria perguntar se você poderia verificar sua versão do SQL novamente, porque estou simplesmente curioso sobre como / por que esse evento de espera está aparecendo para essa versão.

Quanto à espera na rede, sim, isso pode acontecer mesmo se você estiver trabalhando em um servidor independente. Você verificou as configurações das suas placas de rede? Eu estou querendo saber se eles são um problema.

No final do dia, existem apenas alguns gargalos de recursos possíveis: memória, CPU, E / S de disco, rede e bloqueio. Você indicou que CPU e E / S não é o problema e você tem um evento de espera de NETWORK_IO; portanto, sugiro que você examine essas placas de NIC primeiro.

SQLRockstar
fonte
1
Isso NETWORK_IOé mostrado porque o OP está usando eventos estendidos. Ele nunca foi atualizado emsys.dm_xe_map_values
Martin Smith
Estou pensando o mesmo SQLRockstar, exatamente o que poderia estar acontecendo. Eu tentei desativar completamente as placas de rede. Martin apontou que alguns arquivos antigos ainda podem estar lá. Atualizarei os resultados amanhã para ver se isso muda alguma coisa.
Djof 22/02/12
Além disso, pode ajudar se pudermos ver os planos de execução para as instruções.
SQLRockstar 22/02