Въздействие на плана за изпълнение върху ASYNC_NETWORK_IO изчаквания – част 1

Моят непосредствен отговор на това би бил, че някой тълкува погрешно причината и следствието от това, тъй като се среща типът на изчакване ASYNC_NETWORK_IO, когато машината има резултати за изпращане по TDS до клиента, но няма налични TDS буфери на връзката, за да ги изпрати На. Най-общо казано, това означава, че клиентската страна не консумира резултатите ефективно, но въз основа на последвалата дискусия станах достатъчно заинтригуван, за да направя някои тестове дали планът за изпълнение действително ще повлияе значително на изчакването на ASYNC_NETWORK_IO.

За да обобщим:фокусирането върху ASYNC_NETWORK_IO изчаква самостоятелно, тъй като показателят за настройка е грешка. Колкото по-бързо се изпълнява заявката, толкова по-високо ще се натрупа този тип чакане, дори ако клиентът консумира резултати възможно най-бързо. (Вижте също скорошната публикация на Грег за фокусирането само върху изчакването като цяло.)

Тестова конфигурация

За да стартирате тестовете за това, беше генерирана много проста таблица въз основа на пример, предоставен ми по имейл от друг член на общността, който демонстрира промяна в типа на чакане, но също така имаше съвсем различна заявка между двете тестове с допълнителна таблица, използвана във втория тест, и имаше коментар за изключване на резултатите, което премахва значителната част от този тип чакане като начало, така че не е само промяна на плана.

Забележка:Бих искал да отбележа, че това изобщо не е отрицателно изявление към никого; Последвалата дискусия и допълнителни тестове, дошли от предоставеното оригинално възпроизвеждане, бяха много образователни и доведоха до по-нататъшни изследвания за разбиране на този тип чакане като цяло. Оригиналното възпроизвеждане ДИ демонстрира разлика, но с допълнителни промени, които не бяха част от първоначалния въпрос, както е зададен.

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

Използвайки тази таблица като основен набор от данни за тестване на различни форми на планове с помощта на подсказки, бяха използвани следните заявки:

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;

Тъй като изпълнявах тези заявки на SQL Server 2019 CU1, плановете за изпълнение включваха действителната информация за статистиката за чакане, свързана с изпълнението на заявката.

Забележка: Оптимизаторът ще използва Merge Join, без да се прилагат подсказки за този конкретен набор от данни и заявка.

Първоначални резултати от теста

За първоначалните тестове просто използвах SSMS за стартиране на заявките и събрах плана за действително изпълнение, за да сравня информацията за изчакване, свързана с всяка заявка, която е показана по-долу. Имайте предвид, че за този размер на данни изминалите времена не се различават значително, нито времето за изчакване или броя на чакането за 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" />

СЛИВАНЕ ПРИСЪЕДИНЯВАНЕ

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

СЪЕДИНЯВАНЕ НА ПРИМКА

<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" />

Това обаче не беше мястото, където исках да спра тестването, защото моят собствен опит многократно показва, че Management Studio е много неефективен потребител на резултати от SQL Server и може сам по себе си причини ASYNC_NETWORK_IO изчаква да се появи. Така че реших да променя начина, по който тествах нещата и отидох на SQLCMD изпълнение на заявките.

Тестване с SQLCMD

Тъй като използвам SQLCMD много за демонстрации, докато представям, създадох файл testscript.sql със следното съдържание:

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

Това беше изпълнено от командния ред по следния начин и по време на 5-секундното забавяне прозорецът беше минимизиран, за да позволи изпълнението да не изобразява и превърта резултатите по време на обработка:

За да заснема действителните планове за изпълнение, отидох със сесия с разширени събития, събираща събитието query_post_execution_showplan, което, в задна дата, на SQL Server 2019, мислех, че трябваше да използвам query_post_execution_plan_profile вместо това, за да използвам леката статистика за изпълнение на заявка, но профилиране на това инфраструктурно събитие v3 не връща информацията за WaitStats или QueryTimeStats, освен ако query_post_execution_showplan също не е активиран в същото време. Освен това, тъй като това е изолирана машина за тестване без друго работно натоварване, въздействието на стандартното профилиране всъщност не е толкова голямо притеснение тук.

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" />

СЛИВАНЕ ПРИСЪЕДИНЯВАНЕ

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

СЪЕДИНЯВАНЕ НА ПРИМКА

<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" />

Това всъщност не се оказа по-бърз начин за изпълнение на заявката и производителността всъщност беше намалена чрез използване на помощната програма на командния ред за изпълнение на заявката, дори когато прозорецът е минимизиран и резултатите не се превъртат видимо. При отворен прозорец времето за изпълнение на HASH е 15708ms, а времето за изчакване на ASYNC_NETWORK_IO е 15126ms. Това обаче показва, че за същите точни резултати производителността на клиента, който използва резултатите, влияе както на времето за изчакване, така и на времето за изпълнение на заявката.

Влияние на паралелизма?

Едно от нещата, които забелязах, беше, че само два от плановете бяха изпълнени с паралелизъм, въз основа на съществуването на изчаквания CXPACKET и LATCH_EX в XML плана за изпълнение. Така че се чудех какво въздействие би имало налагането на план за серийно изпълнение върху изпълнението на същите тези заявки с помощта на OPTION (MAXDOP 1).

HASH JOIN

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

СЛИВАНЕ ПРИСЪЕДИНЯВАНЕ

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

СЪЕДИНЯВАНЕ НА ПРИМКА

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

Забележете тук, че общият брой на чаканията не е намалял значително. Само планът за присъединяване към сериен цикъл има голяма промяна в броя на изчакванията или общото време на изчакване, свързано с него, и в изолация това не означава, че е положителна полза, времето за изпълнение на заявката не е значително подобрено и може да има други фактори, които са повлияли на резултатите от този конкретен тест.

Таблицата по-долу обобщава времето за изчакване и броя на ASYNC_NETWORK_IO за всеки от тестовете.

Резюме

Въпреки че разследването на тази публикация не обхваща всеки отделен аспект на промените в плана или типа на изчакване ASYNC_NETWORK_IO, то демонстрира, че това изчакване не се влияе значително от плана за изпълнение, който се използва за изпълнение на заявка. Бих класифицирал този тип изчакване почти като типа на чакане CXPACKET, когато извършвам анализ на сървър като цяло; нормално да се види за повечето работни натоварвания и освен ако не е невероятно изкривено и има други проблеми с производителността, сочещи към бавното потребление на резултати от клиенти, като блокиране с водещ блокер, чакащ ASYNC_NETWORK_IO, тогава нещо, което трябва да се игнорира като просто „част от подписа за нормално чакане за натоварването".