Observer Overhead- och väntetypssymptom

Många människor använder väntestatistik som en del av deras övergripande felsökningsmetod för prestanda, liksom jag, så frågan jag ville utforska i det här inlägget handlar om väntetyper förknippade med observatörskostnader. Med observatörskostnader menar jag påverkan på SQL Server-arbetsbelastning som orsakas av SQL Profiler, spårningar på serversidan eller utökade händelsesessioner. För mer om ämnet observer overhead, se följande två inlägg från min kollega Jonathan Kehayias :

• Mätning av "Observer Overhead" av SQL Trace vs. Extended Events
• Effekten av query_post_execution_showplan Extended Event i SQL Server 2012

Så i det här inlägget skulle jag vilja gå igenom några varianter av observatörsoverhead och se om vi kan hitta konsekventa väntetyper förknippade med den uppmätta nedbrytningen. Det finns en mängd olika sätt som SQL Server-användare implementerar spårning i sina produktionsmiljöer, så dina resultat kan variera, men jag ville täcka några breda kategorier och rapportera tillbaka om vad jag hittade:

• Användning av SQL Profiler-session
• Spåranvändning på serversidan
• Spåra användning på serversidan, skriva till en långsam I/O-väg
• Utökad händelseanvändning med ett ringbuffertmål
• Utökad användning av händelser med ett filmål
• Utökad händelseanvändning med ett filmål på en långsam I/O-sökväg
• Utökad händelseanvändning med ett filmål på en långsam I/O-sökväg utan händelseförlust

Du kan antagligen komma på andra varianter av temat och jag inbjuder dig att dela med dig av alla intressanta rön om observatörsoverhead och väntestatistik som en kommentar i det här inlägget.

Baslinje

För testet använde jag en virtuell VMware-maskin med fyra vCPU:er och 4 GB RAM. Min virtuella maskingäst var på OCZ Vertex SSD:er. Operativsystemet var Windows Server 2008 R2 Enterprise och versionen av SQL Server är 2012, SP1 CU4.

När det gäller "arbetsbelastningen" använder jag en skrivskyddad fråga i en loop mot 2008 års kreditprovsdatabas, inställd på GO 10 000 000 gånger.

USE [Credit];
GO
 
SELECT TOP 1 
     [member].[member_no],
     [member].[lastname],
     [payment].[payment_no],
     [payment].[payment_dt],
     [payment].[payment_amt]
FROM [dbo].[payment]
INNER JOIN [dbo].[member]
ON [member].[member_no] = [payment].[member_no];
GO 10000000

Jag kör också den här frågan via 16 samtidiga sessioner. Slutresultatet på mitt testsystem är 100 % CPU-användning över alla vCPU:er på den virtuella gästen och i genomsnitt 14 492 batchförfrågningar per sekund under en period på två minuter.

När det gäller händelsespårningen använde jag i varje test Showplan XML Statistics Profile för spårningstesterna SQL Profiler och Server-side – och query_post_execution_showplan för utökade evenemangssessioner. Exekutivplanshändelser är mycket dyra, det är just därför jag valde dem så att jag kunde se om jag under extrema omständigheter kunde härleda teman av väntetyp eller inte.

För att testa ackumulering av väntetyp under en testperiod använde jag följande fråga. Inget märkvärdigt – bara att rensa statistiken, vänta 2 minuter och sedan samla de 10 bästa vänteackumuleringarna för SQL Server-instansen under nedbrytningstestperioden:

-- Clearing the wait stats
 
DBCC SQLPERF('waitstats', clear);
 
WAITFOR DELAY '00:02:00';
GO
 
SELECT TOP 10
     [wait_type],
     [waiting_tasks_count],
     [wait_time_ms]
FROM sys.[dm_os_wait_stats] AS [ws]
ORDER BY [wait_time_ms] DESC;

Observera att jag inte är det filtrera bort bakgrundsväntetyper som vanligtvis filtreras bort, och det beror på att jag inte ville eliminera något som normalt är godartat – men i den här omständigheten faktiskt pekar på ett verkligt område att undersöka vidare.

SQL Profiler Session

Följande tabell visar före- och efter-batchförfrågningar per sekund när du aktiverar en lokal SQL Profiler-spårningsspårning Showplan XML Statistics Profile (kör på samma virtuella dator som SQL Server-instansen):

Du kan se att spårningen av SQL Profiler orsakar en betydande minskning av genomströmningen.

När det gäller ackumulerad väntetid under samma period var de bästa väntetyperna följande (som med resten av testerna i den här artikeln gjorde jag några testkörningar och resultatet var generellt konsekvent):

Väntetypen som hoppar ut för mig är TRACEWRITE – som definieras av Books Online som en väntetyp som "uppstår när spårningsleverantören för SQL Trace-raduppsättning väntar på antingen en ledig buffert eller en buffert med händelser att bearbeta". Resten av väntetyperna ser ut som vanliga väntetyper i bakgrunden som man vanligtvis skulle filtrera bort från din resultatuppsättning. Dessutom pratade jag om ett liknande problem med överspårning i en artikel 2011 som heter Observer overhead – farorna med för mycket spårning – så jag kände till den här väntetypen ibland korrekt pekar på observatörs overhead-problem. Nu i just det fallet jag bloggade om var det inte SQL Profiler, utan en annan applikation som använder rowset-spårningsleverantören (ineffektivt).

Spårning på serversidan

Det var för SQL Profiler, men hur är det med spårning på serversidan? Följande tabell visar före- och efter-batchbegäranden per sekund när du aktiverar en lokal server-side-spårskrivning till en fil:

De bästa väntetyperna var följande (jag gjorde några testkörningar och resultatet var konsekvent):

Den här gången ser vi inte TRACEWRITE (vi använder en filleverantör nu) och den andra spårningsrelaterade väntetypen, den odokumenterade SQLTRACE_INCREMENTAL_FLUSH_SLEEP klättrade upp – men har i jämförelse med det första testet mycket liknande ackumulerad väntetid (120 046 vs. 120 006) – och min kollega Erin Stellato (@erinstellato) pratade om just denna väntetyp i sitt inlägg. . Så om man tittar på de andra väntetyperna är det ingen som hoppar ut som en pålitlig röd flagga.

Server-Side Spåra skrivning till en långsam I/O-väg

Vad händer om vi lägger spårningsfilen på serversidan på långsam disk? Följande tabell visar före- och efter-batchbegäranden per sekund när du aktiverar en lokal spårning på serversidan som skriver till en fil på ett USB-minne:

Som vi kan se – är prestandan avsevärt försämrad – även jämfört med föregående test.

De bästa väntetyperna var följande:

En väntetyp som hoppar ut för detta test är den odokumenterade SQLTRACE_FILE_BUFFER . Inte mycket dokumenterat om den här, men baserat på namnet kan vi göra en välgrundad gissning (särskilt med tanke på det här testets konfiguration).

Utökade händelser till ringbuffertmålet

Låt oss sedan gå igenom resultaten för motsvarande sessioner för utökad evenemang. Jag använde följande sessionsdefinition:

CREATE EVENT SESSION [ApplicationXYZ] ON SERVER
  ADD EVENT sqlserver.query_post_execution_showplan,
  ADD TARGET package0.ring_buffer(SET max_events_limit=(1000))
  WITH (STARTUP_STATE=ON);
GO

Följande tabell visar batchförfrågningar före och efter per sekund när en XE-session aktiveras med ett ringbuffertmål (fångar query_post_execution_showplan händelse):

De bästa väntetyperna var följande:

Ingenting hoppade ut som XE-relaterat, bara bakgrundsuppgift "brus".

Utökade händelser till ett filmål

Vad sägs om att ändra sessionen till att använda ett filmål istället för ett ringbuffertmål? Följande tabell visar före- och efter-batchbegäranden per sekund när du aktiverar en XE-session med ett filmål istället för ett ringbuffertmål:

De bästa väntetyperna var följande:

Ingenting, med undantag för XE_TIMER_EVENT , hoppade ut som XE-relaterad. Bob Wards Wait Type Repository hänvisar till den här som säker att ignorera om det inte var något möjligt fel - men realistiskt sett skulle du märka denna vanligtvis godartade väntetyp om den var på plats 9 på ditt system under en prestandaförsämring? Och vad händer om du redan filtrerar bort det på grund av dess normalt godartade natur?

Utökade händelser till ett långsamt I/O-sökvägsfilmål

Vad händer nu om jag lägger filen på en långsam I/O-väg? Följande tabell visar batchförfrågningar före och efter per sekund när du aktiverar en XE-session med ett filmål på ett USB-minne:

De bästa väntetyperna var följande:

Återigen, inget XE-relaterat hoppar ut förutom XE_TIMER_EVENT .

Utökade händelser till ett långsamt I/O-sökvägsfilmål, ingen händelseförlust

Följande tabell visar före- och efter-batchförfrågningar per sekund när du aktiverar en XE-session med ett filmål på ett USB-minne, men den här gången utan att tillåta händelseförlust (EVENT_RETENTION_MODE=NO_EVENT_LOSS) – vilket inte rekommenderas och du kommer att se i resultaten varför det kan vara:

De bästa väntetyperna var följande:

Med den extrema genomströmningsminskningen ser vi XE_BUFFERMGR_FREEBUF_EVENT hoppa till nummer ett på våra ackumulerade väntetidsresultat. Den här är dokumenteras i Books Online, och Microsoft berättar för oss att denna händelse är associerad med XE-sessioner som är konfigurerade för ingen händelseförlust och där alla buffertar i sessionen är fulla.

Observatörspåverkan

Bortsett från väntetyperna var det intressant att notera vilken inverkan varje observationsmetod hade på vår arbetsbelastnings förmåga att behandla batchförfrågningar:

Inverkan av olika observationsmetoder på batchförfrågningar per sekund

För alla tillvägagångssätt fanns det en signifikant – men inte chockerande – träff jämfört med vår baslinje (ingen observation); Den största smärtan kändes dock när du använde Profiler, när du använde Server-Side Trace till en långsam I/O-sökväg, eller utökade händelser till ett filmål på en långsam I/O-sökväg – men bara när den konfigurerades för ingen händelseförlust. Med händelseförlust fungerade den här installationen faktiskt i nivå med ett filmål till en snabb I/O-sökväg, förmodligen för att den kunde släppa mycket fler händelser.

Sammanfattning

Jag testade inte alla möjliga scenarier och det finns säkert andra intressanta kombinationer (för att inte tala om olika beteenden baserade på SQL Server-versionen), men den viktigaste slutsatsen jag drar från denna utforskning är att du inte alltid kan lita på en uppenbar ackumulering av väntetyp. pekare när du står inför ett observatörsscenario. Baserat på testerna i det här inlägget, visade endast tre av sju scenarier en specifik väntetyp som potentiellt skulle kunna hjälpa dig att peka i rätt riktning. Redan då – dessa tester var på ett kontrollerat system – och ofta filtrerar folk bort de tidigare nämnda väntetyperna som godartade bakgrundstyper – så att du kanske inte ser dem alls.

Med tanke på detta, vad kan du göra? För prestandaförsämring utan tydliga eller uppenbara symtom, rekommenderar jag att du breddar omfattningen för att fråga om spår och XE-sessioner (som en åtskillnad – jag rekommenderar också att du utökar omfattningen om systemet är virtualiserat eller kan ha felaktiga strömalternativ). Till exempel, som en del av felsökning av ett system, kontrollera sys.[traces] och sys.[dm_xe_sessions] för att se om något körs på systemet som är oväntat. Det är ett extra lager till det du behöver oroa dig för, men att göra några snabba valideringar kan spara en hel del tid.