Database
 sql >> Base de Dados >  >> RDS >> Database

Impacto do Plano de Execução nas Esperas ASYNC_NETWORK_IO - Parte 1


Algumas semanas atrás, uma pergunta interessante foi feita na hashtag #SQLHelp no Twitter sobre o impacto dos planos de execução no tipo de espera ASYNC_NETWORK_IO, e gerou algumas opiniões divergentes e muita discussão boa.

https://twitter.com/shawndube/status/1225476846537650176

Minha resposta imediata para isso seria que alguém está interpretando mal a causa e o efeito disso, já que o tipo de espera ASYNC_NETWORK_IO é encontrado quando o mecanismo tem resultados para enviar por TDS para o cliente, mas não há buffers TDS disponíveis na conexão para enviá-los em. De um modo geral, isso significa que o lado do cliente não está consumindo os resultados com eficiência, mas com base na discussão que se seguiu fiquei intrigado o suficiente para fazer alguns testes sobre se um plano de execução realmente afetaria significativamente as esperas de ASYNC_NETWORK_IO.

Para resumir:Concentrar-se em ASYNC_NETWORK_IO espera sozinho como uma métrica de ajuste é um erro. Quanto mais rápido uma consulta for executada, maior será o acúmulo desse tipo de espera, mesmo que o cliente esteja consumindo os resultados o mais rápido possível. (Veja também o post recente de Greg sobre focar apenas em esperas em geral.)

Configuração de teste


Para executar os testes para isso, uma tabela muito simples foi gerada com base em um exemplo que me foi fornecido por e-mail de outro membro da comunidade, que demonstrou uma mudança no tipo de espera, mas também teve uma consulta totalmente diferente entre os dois testes com uma tabela adicional sendo usada no segundo teste e havia um comentário para desativar os resultados, o que remove a parte significativa desse tipo de espera para começar, portanto, não é apenas uma mudança de plano.

Nota:gostaria de salientar que esta não é uma declaração negativa para ninguém; a discussão que se seguiu e outros testes que vieram da reprodução original que foi fornecida foi muito educacional e levou a mais pesquisas para entender esse tipo de espera em geral. A reprodução original DID demonstrou uma diferença, mas com alterações adicionais que não faziam parte da questão original como posta. 
DROP TABLE IF EXISTS [DemoTable];
 
CREATE TABLE [DemoTable] (
  ID INT PRIMARY KEY,
  FILLER VARCHAR(100)
);
 
INSERT INTO [DemoTable] WITH (TABLOCK)
SELECT TOP (250000) ROW_NUMBER() OVER (ORDER BY (SELECT NULL)), REPLICATE('Z', 50)
  FROM master..spt_values t1
  CROSS JOIN master..spt_values t2
  CROSS JOIN master..spt_values t3
  OPTION (MAXDOP 1);
GO

Usando esta tabela como um conjunto de dados base para testar diferentes formas de plano usando dicas, as seguintes consultas foram usadas:
SELECT t1.ID, t2.FILLER, t2.FILLER
  FROM [DemoTable] t1
  INNER HASH JOIN [DemoTable] t2 ON t1.ID = t2.ID;
 
  SELECT t1.ID, t2.FILLER, t2.FILLER
  FROM [DemoTable] t1
  INNER MERGE JOIN [DemoTable] t2 ON t1.ID = t2.ID;
 
  SELECT t1.ID, t2.FILLER, t2.FILLER
  FROM [DemoTable] t1
  INNER LOOP JOIN [DemoTable] t2 ON t1.ID = t2.ID;

Como eu estava executando essas consultas no SQL Server 2019 CU1, os planos de execução incluíam as informações reais de estatísticas de espera relacionadas à execução da consulta.

Observação: O otimizador usaria um Merge Join sem que as dicas fossem aplicadas para esse conjunto de dados e consulta específicos.

Resultados do teste inicial


Para os testes iniciais, simplesmente usei o SSMS para executar as consultas e coletei o plano Real Execution para comparar as informações de espera associadas a cada consulta, mostradas abaixo. Observe que, para esse tamanho de dados, os tempos decorridos não são significativamente diferentes, nem os tempos de espera ou as contagens de espera para ASYNC_NETWORK_IO.

HASH JOIN

<WaitStats>
  <Wait WaitType="CXPACKET"         WaitTimeMs="18393" WaitCount="8415" />
  <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="4394"  WaitCount="6635" />
  <Wait WaitType="HTDELETE"         WaitTimeMs="957"   WaitCount="6"    />
  <Wait WaitType="HTBUILD"          WaitTimeMs="4"     WaitCount="6"    />
  <Wait WaitType="HTREPARTITION"    WaitTimeMs="3"     WaitCount="6"    />
  <Wait WaitType="CMEMTHREAD"       WaitTimeMs="3"     WaitCount="14"   />
  <Wait WaitType="LATCH_EX"         WaitTimeMs="2"     WaitCount="8"    />
</WaitStats>
<QueryTimeStats CpuTime="1068" ElapsedTime="4961" />

MERGE JOIN

<WaitStats>
  <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="3169" WaitCount="6592" />
</WaitStats>
<QueryTimeStats CpuTime="792" ElapsedTime="3933" />

LOOP JOIN

<WaitStats>
  <Wait WaitType="CXPACKET"         WaitTimeMs="13690" WaitCount="8286" />
  <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="3576"  WaitCount="6631" />
  <Wait WaitType="LATCH_EX"         WaitTimeMs="1"     WaitCount="3"    />
</WaitStats>
<QueryTimeStats CpuTime="2172" ElapsedTime="4084" />

No entanto, não era aqui que eu queria parar de testar, porque minha própria experiência mostrou repetidamente que o Management Studio é um consumidor muito ineficiente de resultados do SQL Server e pode causar ASYNC_NETWORK_IO aguarda para ocorrer. Então, decidi mudar como estava testando as coisas e fui para uma execução SQLCMD das consultas.

Teste com SQLCMD


Como uso muito o SQLCMD para demonstrações durante a apresentação, criei um arquivo testscript.sql com o seguinte conteúdo:
PRINT 'Minimize Screen';
GO
 
WAITFOR DELAY '00:00:05';
GO
 
SELECT t1.ID, t2.FILLER, t2.FILLER
  FROM [DemoTable] t1
  INNER HASH JOIN [DemoTable] t2 ON t1.ID = t2.ID;
GO
 
SELECT t1.ID, t2.FILLER, t2.FILLER
  FROM [DemoTable] t1
  INNER MERGE JOIN [DemoTable] t2 ON t1.ID = t2.ID;
GO
 
SELECT t1.ID, t2.FILLER, t2.FILLER
  FROM [DemoTable] t1
  INNER LOOP JOIN [DemoTable] t2 ON t1.ID = t2.ID;
GO

Isso foi executado a partir da linha de comando da seguinte maneira e, durante o atraso de 5 segundos, a janela foi minimizada para permitir que a execução não renderizasse e role os resultados durante o processamento:
sqlcmd -S.\SQL2019 -i testscript.sql -dAdventureWorks2017
Para capturar os planos de execução reais, fui com uma sessão de Eventos Estendidos coletando o evento query_post_execution_showplan que, em retrospectiva, no SQL Server 2019, pensei que deveria ter usado query_post_execution_plan_profile em vez de usar a implementação de infraestrutura v3 de criação de perfil de estatísticas de execução de consulta leve, mas esse evento não retorna as informações de WaitStats ou QueryTimeStats, a menos que query_post_execution_showplan também esteja habilitado ao mesmo tempo. Além disso, como esta é uma máquina de teste isolada sem outra carga de trabalho, os impactos da criação de perfil padrão não são uma preocupação tão grande aqui. 
CREATE EVENT SESSION [Actual Plan] ON SERVER 
  ADD EVENT sqlserver.query_post_execution_showplan
  (ACTION(sqlserver.session_id));

HASH JOIN

<WaitStats>
  <Wait WaitType="CXPACKET"         WaitTimeMs="45722" WaitCount="8674" />
  <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="11321" WaitCount="6610" />
  <Wait WaitType="HTDELETE"         WaitTimeMs="1174"  WaitCount="6"    />
  <Wait WaitType="HTREPARTITION"    WaitTimeMs="4"     WaitCount="6"    />
  <Wait WaitType="HTBUILD"          WaitTimeMs="3"     WaitCount="5"    />
  <Wait WaitType="LATCH_EX"         WaitTimeMs="2"     WaitCount="7"    />
</WaitStats>
<QueryTimeStats ElapsedTime="11874" CpuTime="1070" />

MERGE JOIN

<WaitStats>
  <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="10837" WaitCount="6602" />
</WaitStats>
<QueryTimeStats ElapsedTime="11597" CpuTime="789" />

LOOP JOIN

<WaitStats>
  <Wait WaitType="CXPACKET"         WaitTimeMs="43587" WaitCount="8620" />
  <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="11177" WaitCount="6612" />
  <Wait WaitType="LATCH_EX"         WaitTimeMs="1"     WaitCount="3"    />
</WaitStats>
<QueryTimeStats ElapsedTime="11696" CpuTime="2221" />

Na verdade, isso não funcionou como uma maneira mais rápida de executar a consulta, e o desempenho foi realmente reduzido usando o utilitário de linha de comando para executar a consulta, mesmo quando a janela é minimizada e não rola visivelmente os resultados. Com a janela aberta o tempo de execução do HASH foi de 15708ms e o tempo de espera do ASYNC_NETWORK_IO foi de 15126ms. No entanto, isso demonstra que, para os mesmos resultados exatos, o desempenho do cliente consumindo os resultados afeta o tempo de espera e o tempo de execução da consulta.

Impacto do paralelismo?


Uma das coisas que notei foi que apenas dois dos planos foram executados com paralelismo, baseado na existência das esperas CXPACKET e LATCH_EX no XML do plano de execução. Então eu me perguntei que tipo de impacto forçar um plano de execução serial teria na execução dessas mesmas consultas usando OPTION (MAXDOP 1).

HASH JOIN

<WaitStats>
  <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="4047" WaitCount="6379" />
</WaitStats>
<QueryTimeStats CpuTime="602" ElapsedTime="4619" />

COMBINAR PARTICIPAÇÃO

<WaitStats>
  <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="3699" WaitCount="6608" />
</WaitStats>
<QueryTimeStats CpuTime="810" ElapsedTime="4478" />

LOOP JOIN

<WaitStats>
  <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="2083" WaitCount="5385" />
</WaitStats>
<QueryTimeStats CpuTime="1859" ElapsedTime="3918" />

Observe aqui que as contagens gerais de espera não diminuíram significativamente. Apenas o plano de junção de loop serial tem uma grande mudança no número de esperas ou quantidade total de tempo de espera associado a ele e, isoladamente, isso não significa que seja um benefício positivo, o tempo de execução da consulta não foi significativamente melhorado e pode haver outros fatores que afetaram os resultados desse teste específico.

A tabela abaixo resume o tempo de espera e a contagem de ASYNC_NETWORK_IO para cada um dos testes.
Tipo de plano Linhas Contagem de Espera Tempo de espera ExecTime AppName MAXDOP 1 Paralelo
Hash 250.000 6.635 4.394 4.961 SSMS N S
Mesclar 250.000 6.592 3.169 3.933 SSMS N N
Loop 250.000 6.631 3.576 4.084 SSMS N S
Hash 250.000 6.610 11.321 11.874 SQLCMD N S
Mesclar 250.000 6.602 10.837 11.597 SQLCMD N N
Loop 250.000 6.612 11.177 11.696 SQLCMD N S
Hash 250.000 6.379 4.047 4.619 SSMS S N
Mesclar 250.000 6.608 3.699 4.479 SSMS S N
Loop 250.000 5.385 2.083 3.918 SSMS S N

Resumo


Embora a investigação desta postagem não cubra todos os aspectos das alterações de plano ou o tipo de espera ASYNC_NETWORK_IO, ela demonstra que essa espera não é significativamente afetada pelo plano de execução usado para a execução de uma consulta. Eu classificaria esse tipo de espera quase como o tipo de espera CXPACKET ao realizar a análise de um servidor como um todo; normal de ver para a maioria das cargas de trabalho e a menos que seja incrivelmente distorcido e haja outros problemas de desempenho apontando para um consumo lento de resultados pelos clientes, como o bloqueio com o bloqueador de leads aguardando ASYNC_NETWORK_IO, então algo a ser ignorado como apenas 'parte da assinatura normal de esperas para a carga de trabalho'.