¿Por qué un simple bucle resulta en esperas ASYNC_NETWORK_IO?

19

El siguiente T-SQL tarda unos 25 segundos en mi máquina con SSMS v17.9:

DECLARE @outer_loop INT = 0,
@big_string_for_u VARCHAR(8000);

SET NOCOUNT ON;

WHILE @outer_loop < 50000000
BEGIN
    SET @big_string_for_u = 'ZZZZZZZZZZ';
    SET @outer_loop = @outer_loop + 1;
END;

Acumula 532 ms de ASYNC_NETWORK_IOesperas según ambos sys.dm_exec_session_wait_statsy sys.dm_os_wait_stats. El tiempo de espera total aumenta a medida que aumenta el número de iteraciones de bucle. Usando el wait_completedevento extendido, puedo ver que la espera ocurre aproximadamente cada 43 ms con algunas excepciones:

mesa de espera

Además, puedo obtener las pilas de llamadas que ocurren justo antes de la ASYNC_NETWORK_IOespera:

sqldk.dll!SOS_DispatcherBase::GetTrack+0x7f6c
sqldk.dll!SOS_Scheduler::PromotePendingTask+0x204
sqldk.dll!SOS_Task::PostWait+0x5f
sqldk.dll!SOS_Scheduler::Suspend+0xb15
sqllang.dll!CSECCNGProvider::GetBCryptHandleFromAlgID+0xf6af
sqllang.dll!CSECCNGProvider::GetBCryptHandleFromAlgID+0xf44c
sqllang.dll!SNIPacketRelease+0xd63
sqllang.dll!SNIPacketRelease+0x2097
sqllang.dll!SNIPacketRelease+0x1f99
sqllang.dll!SNIPacketRelease+0x18fe
sqllang.dll!CAutoExecuteAsContext::Restore+0x52d
sqllang.dll!CSQLSource::Execute+0x151b
sqllang.dll!CSQLSource::Execute+0xe13
sqllang.dll!CSQLSource::Execute+0x474
sqllang.dll!SNIPacketRelease+0x165d
sqllang.dll!CValOdsRow::CValOdsRow+0xa92
sqllang.dll!CValOdsRow::CValOdsRow+0x883
sqldk.dll!ClockHand::Statistic::RecordClockHandStats+0x15d
sqldk.dll!ClockHand::Statistic::RecordClockHandStats+0x638
sqldk.dll!ClockHand::Statistic::RecordClockHandStats+0x2ad
sqldk.dll!SystemThread::MakeMiniSOSThread+0xdf8
sqldk.dll!SystemThread::MakeMiniSOSThread+0xf00
sqldk.dll!SystemThread::MakeMiniSOSThread+0x667
sqldk.dll!SystemThread::MakeMiniSOSThread+0xbb9

Finalmente, noté que SSMS usa una sorprendente cantidad de CPU durante el ciclo (aproximadamente medio núcleo en promedio). No puedo entender qué hace SSMS durante ese tiempo.

¿Por qué un bucle simple causa ASYNC_NETWORK_IOesperas cuando se ejecuta a través de SSMS? El único resultado que parezco obtener del cliente de esta ejecución de consulta es "Comandos completados correctamente". mensaje.

Joe Obbish
fuente

Respuestas:

31

La documentación para SET NOCOUNTdice:

SET NOCOUNT ONevita el envío de DONE_IN_PROCmensajes al cliente para cada declaración en un procedimiento almacenado. Para los procedimientos almacenados que contienen varias declaraciones que no devuelven muchos datos reales, o para los procedimientos que contienen bucles Transact-SQL, la configuración SET NOCOUNTde ONpuede proporcionar un aumento significativo del rendimiento, ya que el tráfico de red se reduce considerablemente.

No está ejecutando las instrucciones en un procedimiento almacenado, por lo que SQL Server envía DONEtokens (código 0xFD) para indicar el estado de finalización de cada instrucción SQL. Estos mensajes se difieren y se envían de forma asíncrona cuando el paquete de red está lleno. Cuando el cliente no consume paquetes de red lo suficientemente rápido, eventualmente los búferes se llenan y la operación se convierte en bloqueo para SQL Server, generando las ASYNC_NETWORK_IOesperas.

Tenga en cuenta que los DONEtokens son diferentes de DONEINPROC(código 0xFF) como se indica en la documentación:

  • Se DONEdevuelve un token para cada instrucción SQL en el lote SQL, excepto las declaraciones de variables.

  • Para la ejecución de las sentencias SQL dentro de procedimientos almacenados, DONEPROCy DONEINPROClos tokens se utilizan en lugar de DONEfichas.

Verá una reducción dramática en las ASYNC_NETWORK_IOesperas usando:

CREATE PROCEDURE #P AS
SET NOCOUNT ON;

DECLARE
    @outer_loop integer = 0,
    @big_string_for_u varchar(8000);


WHILE @outer_loop < 5000000
BEGIN
    SET @big_string_for_u = 'ZZZZZZZZZZ';
    SET @outer_loop = @outer_loop + 1;
END;
GO
EXECUTE dbo.#P;

También podría usar sys.sp_executesqlpara lograr el mismo resultado.

Ejemplo de seguimiento de pila capturado justo cuando ASYNC_NETWORK_IOcomienza una espera:

enviando un paquete

Un paquete TDS de ejemplo como se ve en la función en línea sqllang!srv_completioncode_ex<1>tenía los siguientes 13 bytes:

fd 01 00 c1 00 01 00 00 00 00 00 00 00          

Que decodifica a:

  • TokenType = 0xfd DONE_TOKEN
  • Estado = 0x0001 DONE_MORE
  • CurCmd = 0x00c1 (193)
  • DoneRowCount = 0x00000001 (1)

En última instancia, el número de ASYNC_NETWORK_IOesperas depende del cliente y el controlador, y de lo que hace, si es que hay algo, con todos los DONEmensajes. Al probar con un bucle 1/10 del tamaño dado en la pregunta (5,000,000 iteraciones de bucle), encontré que SSMS se ejecutó durante aproximadamente 4 segundos con 200-300 ms de esperas. sqlcmdcorrió durante 2-3 segundos con un solo dígito ms espera; osqlcasi el mismo tiempo de ejecución con alrededor de 10 ms de esperas.

El peor cliente de lejos para esta prueba fue Azure Data Studio. Funcionó por casi 6 horas:

Anuncios

Paul White dice GoFundMonica
fuente