Dlaczego prosta pętla powoduje, że ASYNC_NETWORK_IO czeka?

Następujący T-SQL zajmuje około 25 sekund na moim komputerze z SSMS 17.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;

Gromadzi 532 ms ASYNC_NETWORK_IOoczekiwań, zarówno według, jak sys.dm_exec_session_wait_statsi sys.dm_os_wait_stats. Całkowity czas oczekiwania wzrasta wraz ze wzrostem liczby iteracji pętli. Za pomocą wait_completedzdarzenia rozszerzonego widzę, że oczekiwanie odbywa się mniej więcej co 43 ms, z kilkoma wyjątkami:

Ponadto mogę uzyskać stosy połączeń, które występują tuż przed ASYNC_NETWORK_IOczekaniem:

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

Wreszcie zauważyłem, że SSMS wykorzystuje zaskakującą ilość procesora podczas pętli (średnio około połowy rdzenia). Nie jestem w stanie dowiedzieć się, co robi SSMS w tym czasie.

Dlaczego prosta pętla powoduje ASYNC_NETWORK_IOoczekiwanie, gdy zostanie wykonana przez SSMS? Wydaje mi się, że jedynym wyjściem, które otrzymuję od klienta po wykonaniu tego zapytania jest „Polecenia zakończone pomyślnie”. wiadomość.

Dokumentacja dla SET NOCOUNTmówi:

SET NOCOUNT ONzapobiega wysyłaniu DONE_IN_PROCkomunikatów do klienta dla każdej instrukcji w procedurze przechowywanej. Dla procedur przechowywanych, które zawierają kilka stwierdzeń, które nie zwracają wiele rzeczywistych danych, lub za procedury, które zawierają pętle Transact-SQL, ustawienie SET NOCOUNTdo ONmoże zapewnić znaczący wzrost wydajności, ponieważ ruch w sieci jest znacznie zmniejszona.

Nie uruchamiasz instrukcji w procedurze przechowywanej, więc SQL Server wysyła DONEtokeny (kod 0xFD) wskazujące status ukończenia każdej instrukcji SQL. Te wiadomości są odraczane i wysyłane asynchronicznie, gdy pakiet sieciowy jest pełny. Gdy klient nie zużywa pakietów sieciowych wystarczająco szybko, ostatecznie bufory zapełniają się, a operacja blokuje SQL Server, generując ASYNC_NETWORK_IOoczekiwania.

Uwaga: DONEtokeny różnią się od DONEINPROC(kodu 0xFF), jak zauważa dokumentacja:

• DONETokena jest zwracana dla każdej instrukcji SQL w SQL partii z wyjątkiem deklaracji zmiennych.

• Do wykonywania instrukcji SQL w ramach procedur przechowywanych, DONEPROCa DONEINPROCtokeny są używane zamiast DONEtokenów.

Zauważysz radykalne zmniejszenie liczby ASYNC_NETWORK_IOoczekujących dzięki:

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;

Możesz także użyć sys.sp_executesqldo osiągnięcia tego samego rezultatu.

Przykładowy ślad stosu przechwycony w momencie rozpoczęcia ASYNC_NETWORK_IOoczekiwania:

Przykładowy pakiet TDS widziany w funkcji inline sqllang!srv_completioncode_ex<1>miał następujące 13 bajtów:

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

Który dekoduje:

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

Ostatecznie liczba ASYNC_NETWORK_IOoczekiwań zależy od klienta i sterownika oraz od tego, co robi, jeśli w ogóle, ze wszystkimi DONEkomunikatami. Testując pętlę 1/10 wielkości podanej w pytaniu (5 000 000 iteracji pętli), znalazłem SSMS działający przez około 4 sekundy z 200-300 ms oczekiwań. sqlcmddziałał przez 2-3 sekundy z jednocyfrowym ms czeka; osqlmniej więcej w tym samym czasie i około 10 ms oczekiwania.

Zdecydowanie najgorszym klientem do tego testu było Azure Data Studio. Trwało to prawie 6 godzin: