Dopad prováděcího plánu na čekání ASYNC_NETWORK_IO – část 1

Abych to shrnul:Zaměření na ASYNC_NETWORK_IO samo o sobě čeká, protože metrika ladění je chyba. Čím rychleji se dotaz spustí, tím více se tento typ čekání pravděpodobně nahromadí, i když klient spotřebovává výsledky co nejrychleji. (Viz také Gregův nedávný příspěvek o zaměření na samotné čekání obecně.)

Test konfigurace

Pro provedení testů byla vygenerována velmi jednoduchá tabulka na základě příkladu, který mi byl poskytnut e-mailem od jiného člena komunity, který demonstroval změnu typu čekání, ale také měl mezi těmito dvěma zcela odlišný dotaz. testy s dodatečnou tabulkou, která byla použita ve druhém testu, a obsahoval komentář k vypnutí výsledků, který pro začátek odstraňuje významnou část tohoto typu čekání, takže nejde jen o samotnou změnu plánu.

Poznámka:Rád bych upozornil, že se nejedná o negativní vyjádření vůči nikomu; Následná diskuse a další testy, které pocházely z původní reprodukce, která byla poskytnuta, byly velmi poučné a vedly k dalšímu výzkumu směrem k celkovému pochopení tohoto typu čekání. Původní reprodukce prokázala rozdíl, ale s dalšími změnami, které nebyly součástí původní otázky, jak byla položena.

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

S použitím této tabulky jako základní datové sady pro testování různých tvarů plánů pomocí rad byly použity následující dotazy:

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;

Vzhledem k tomu, že jsem spouštěl tyto dotazy na SQL Server 2019 CU1, prováděcí plány zahrnovaly skutečné informace o statistikách čekání související s prováděním dotazu.

Poznámka: Optimalizátor by použil spojení sloučení, aniž by pro tuto konkrétní sadu dat a dotaz byly použity rady.

Výsledky úvodního testu

Pro počáteční testy jsem jednoduše použil SSMS ke spuštění dotazů a shromáždil plán skutečného provedení, abych porovnal informace o čekání spojené s každým dotazem, které jsou uvedeny níže. Všimněte si, že pro tuto velikost dat se uplynulé časy výrazně neliší a ani doby čekání nebo počty čekání pro 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" />

SLOUČIT PŘIPOJENÍ

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

Nebylo to však místo, kde jsem chtěl ukončit testování, protože moje vlastní zkušenost opakovaně ukázala, že Management Studio je velmi neefektivní spotřebitel výsledků ze serveru SQL Server a může sám o sobě způsobit ASYNC_NETWORK_IO čeká na výskyt. Rozhodl jsem se tedy změnit způsob, jakým jsem věci testoval, a přešel jsem na SQLCMD provádění dotazů.

Testování pomocí SQLCMD

Protože SQLCMD hodně používám pro ukázky při prezentaci, vytvořil jsem soubor testscript.sql s následujícím obsahem:

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

To bylo provedeno z příkazového řádku následovně a během 5 sekundové prodlevy bylo okno minimalizováno, aby se provádění během zpracování nevykreslovalo a neposouvalo výsledky:

Abych zachytil skutečné plány provádění, šel jsem s relací Extended Events shromažďující událost query_post_execution_showplan, o které jsem si při zpětném pohledu na SQL Server 2019 myslel, že jsem měl místo toho použít query_post_execution_plan_profile, abych použil implementaci infrastruktury profilování statistik provádění dotazů v3 odlehčené, ale tato událost nevrací informace WaitStats nebo QueryTimeStats, pokud není současně povolen také query_post_execution_showplan. Navíc, protože se jedná o izolovaný testovací stroj bez dalšího pracovního zatížení, dopady standardního profilování zde nejsou ve skutečnosti tak velké obavy.

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

SLOUČIT PŘIPOJENÍ

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

To ve skutečnosti nefungovalo jako rychlejší způsob provádění dotazu a výkon byl ve skutečnosti snížen použitím nástroje příkazového řádku k provedení dotazu, i když je okno minimalizováno a výsledky se viditelně neposouvají. S otevřeným oknem byla doba provedení HASH 15708 ms a doba čekání ASYNC_NETWORK_IO byla 15126 ms. To však ukazuje, že u stejných přesných výsledků má výkon klienta spotřebovávajícího výsledky dopad jak na dobu čekání, tak na dobu provedení dotazu.

Vliv paralelismu?

Jedna z věcí, které jsem si všiml, bylo, že pouze dva z plánů byly provedeny paralelně, na základě existence čekání CXPACKET a LATCH_EX v XML plánu provádění. Tak mě zajímalo, jaký dopad by mělo vynucení plánu sériového provádění na provádění stejných dotazů pomocí OPTION (MAXDOP 1).

HASH JOIN

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

SLOUČIT PŘIPOJENÍ

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

Zde si všimněte, že celkový počet čekání se výrazně nesnížil. Pouze plán připojení sériové smyčky má zásadní změnu v počtu čekání nebo celkovém množství čekací doby, která je s ním spojena, a to samo o sobě neznamená, že jde o pozitivní přínos, doba provádění dotazu se výrazně nezlepšila a mohou existovat další faktory, které ovlivnily výsledky tohoto konkrétního testu.

Níže uvedená tabulka shrnuje dobu čekání ASYNC_NETWORK_IO a počet pro každý z testů.

Shrnutí

I když šetření tohoto příspěvku nepokrývá každý jednotlivý aspekt změn plánu nebo typu čekání ASYNC_NETWORK_IO, ukazuje, že toto čekání není významně ovlivněno plánem provádění, který se používá pro provedení dotazu. Tento typ čekání bych klasifikoval téměř jako typ čekání CXPACKET při provádění analýzy serveru jako celku; normální vidět u většiny pracovních zátěží a pokud to není neuvěřitelně zkreslené a neexistují jiné problémy s výkonem poukazující na pomalou spotřebu výsledků klienty, jako je blokování s blokováním potenciálních zákazníků čekajících na ASYNC_NETWORK_IO, pak něco, co je třeba ignorovat jako „součást normálního čekání na podpis“ pracovní zátěž'.