Verkställighetsplanens inverkan på ASYNC_NETWORK_IO väntan – del 1

För några veckor sedan ställdes en intressant fråga på #SQLHelp-hashtaggen på Twitter om inverkan av genomförandeplaner på ASYNC_NETWORK_IO-väntetypen, och den genererade en del olika åsikter och många bra diskussioner.

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

Mitt omedelbara svar på detta skulle vara att någon misstolkar orsaken och effekten av detta, eftersom väntetypen ASYNC_NETWORK_IO påträffas när motorn har resultat att skicka över TDS till klienten men det finns inga tillgängliga TDS-buffertar på anslutningen för att skicka dem på. Generellt sett betyder detta att klientsidan inte konsumerar resultaten effektivt, men baserat på den efterföljande diskussionen blev jag tillräckligt intresserad för att testa huruvida en exekveringsplan faktiskt skulle påverka ASYNC_NETWORK_IO-väntningarna avsevärt.

För att sammanfatta:Att fokusera på ASYNC_NETWORK_IO väntar ensam som en inställningsmetrik är ett misstag. Ju snabbare en fråga körs, desto högre kommer denna väntetyp sannolikt att ackumuleras, även om klienten konsumerar resultat så snabbt som möjligt. (Se även Gregs senaste inlägg om att fokusera på ensam väntan i allmänhet.)

Testa konfiguration

För att köra testerna för detta genererades en mycket enkel tabell baserat på ett exempel som gavs till mig via e-post från en annan medlem av communityn, som visade en förändring i väntetypen, men som också hade en helt annan fråga mellan de två tester med en extra tabell som används i det andra testet, och den hade en kommentar för att stänga av resultaten, vilket tar bort den betydande delen av denna väntetyp till att börja med, så det är inte bara en planändring ensam.

Obs:Jag vill påpeka att detta inte är ett negativt uttalande mot någon alls; den efterföljande diskussionen och ytterligare tester som kom från den ursprungliga reproduktionen som tillhandahölls var mycket lärorik och det ledde till ytterligare forskning för att förstå denna väntetyp överlag. Den ursprungliga reproduktionen visade en skillnad, men med ytterligare ändringar som inte var en del av den ursprungliga frågan som ställdes.

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

Genom att använda den här tabellen som en basdatauppsättning för att testa olika planformer med hjälp av tips, användes följande frågor:

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;

Eftersom jag körde dessa frågor på SQL Server 2019 CU1, inkluderade exekveringsplanerna den faktiska väntestatistikinformationen relaterad till exekveringen av frågan.

Obs! Optimeraren skulle använda en sammanfogning utan att tipsen tillämpas för denna specifika datamängd och fråga.

Initiala testresultat

För de första testerna använde jag helt enkelt SSMS för att köra frågorna och samlade in den faktiska exekveringsplanen för att jämföra vänteinformationen för varje fråga som visas nedan. Observera att för denna datastorlek skiljer sig inte de förflutna tiderna avsevärt, och inte heller väntetiderna eller väntantalet för 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" />

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

Det var dock inte här jag ville sluta testa, eftersom min egen erfarenhet har visat upprepade gånger att Management Studio är en mycket ineffektiv konsument av resultat från SQL Server och själv kan orsaka ASYNC_NETWORK_IO väntar på att inträffa. Så jag bestämde mig för att ändra hur jag testade saker och gick till en SQLCMD-körning av frågorna.

Testar med SQLCMD

Eftersom jag använder SQLCMD mycket för demos när jag presenterar, skapade jag en testscript.sql-fil med följande innehåll:

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

Detta utfördes från kommandoraden enligt följande, och under 5 sekunders fördröjning minimerades fönstret för att tillåta exekveringen att inte rendera och rulla resultat under bearbetning:

För att fånga de faktiska exekveringsplanerna, gick jag med en Extended Events-session och samlade in query_post_execution_showplan-händelsen som, i efterhand, på SQL Server 2019 trodde jag att jag borde ha använt query_post_execution_plan_profile istället för att använda den lätta query execution-statistiken som profilerar infrastruktur v3-implementering, men denna händelse returnerar inte WaitStats- eller QueryTimeStats-informationen om inte query_post_execution_showplan också är aktiverat samtidigt. Dessutom, eftersom detta är en isolerad testmaskin utan någon annan arbetsbelastning, är effekterna av standardprofileringen inte så stora problem här.

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

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

Detta fungerade faktiskt inte för att vara ett snabbare sätt att köra frågan, och prestandan reducerades faktiskt genom att använda kommandoradsverktyget för att köra frågan, även när fönstret är minimerat och inte synligt rullade resultaten. Med fönstret öppet var HASH-exekveringstiden 15708ms och ASYNC_NETWORK_IO väntetiden var 15126ms. Detta visar dock att för exakt samma resultat påverkar prestanda för klienten som konsumerar resultaten både väntetiden och exekveringstiden för frågan.

Parallellism Impact?

En av de saker som jag märkte var att endast två av planerna hade utförts med parallellitet, baserat på förekomsten av CXPACKET och LATCH_EX väntar i exekveringsplanen XML. Så jag undrade vilken typ av påverkan att tvinga fram en seriell exekveringsplan skulle ha på utförandet av samma frågor med OPTION (MAXDOP 1).

HASH JOIN

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

SAMMANSLUTNING JOIN

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

Observera här att det totala väntetalet inte har minskat nämnvärt. Endast den seriella loop-anslutningsplanen har en stor förändring i antalet väntetider eller den totala väntetiden, och isolerat betyder det inte att det är en positiv fördel, exekveringstiden för frågan förbättrades inte avsevärt och det kan finnas andra faktorer som påverkade resultatet av det specifika testet.

Tabellen nedan sammanfattar ASYNC_NETWORK_IO väntetiden och antalet för vart och ett av testerna.

Sammanfattning

Även om det här inläggets undersökning inte täcker varje enskild aspekt av planändringar eller väntetypen ASYNC_NETWORK_IO, visar den att denna väntan inte påverkas nämnvärt av exekveringsplanen som används för att köra en fråga. Jag skulle klassificera denna väntetyp nästan som CXPACKET-väntetypen när jag utför analys av en server som helhet; normalt att se för de flesta arbetsbelastningar och såvida det inte är otroligt skevt och det finns andra prestandaproblem som pekar på långsam konsumtion av resultat av klienter som att blockera med lead-blockeraren som väntar på ASYNC_NETWORK_IO, då något som ska ignoreras som bara 'en del av den normala väntar-signaturen för arbetsbördan'.