Min kollega Steve Wright (blog | @SQL_Steve) stillede mig et spørgsmål for nylig om et mærkeligt resultat, han så. For at teste noget funktionalitet i vores seneste værktøj, SQL Sentry Plan Explorer PRO, havde han fremstillet en bred og stor tabel og kørte en række forespørgsler mod den. I et tilfælde returnerede han en masse data, men STATISTICS IO
viste, at meget få læsninger fandt sted. Jeg pingede nogle personer på #sqlhelp, og da det så ud til, at ingen havde set dette problem, tænkte jeg, at jeg ville blogge om det.
TL;DR-version
Kort sagt, vær meget opmærksom på, at der er nogle scenarier, hvor du ikke kan stole på STATISTICS IO
at fortælle dig sandheden. I nogle tilfælde (denne involverer TOP
og parallelisme), vil det i høj grad underrapportere logiske læsninger. Dette kan få dig til at tro, at du har en meget I/O-venlig forespørgsel, når du ikke har det. Der er andre mere oplagte tilfælde – såsom når du har en masse I/O gemt væk ved brug af skalære brugerdefinerede funktioner. Vi mener, at Plan Explorer gør disse tilfælde mere indlysende; denne er dog lidt vanskeligere.
Problemforespørgslen
Tabellen har 37 millioner rækker, op til 250 bytes pr. række, omkring 1 million sider og meget lav fragmentering (0,42 % på niveau 0, 15 % på niveau 1 og 0 ud over det). Der er ingen beregnede kolonner, ingen UDF'er i spil og ingen indekser undtagen en klynget primærnøgle på den førende INT
kolonne. En simpel forespørgsel, der returnerer 500.000 rækker, alle kolonner, ved hjælp af TOP
og SELECT *
:
SET STATISTICS IO ON; SELECT TOP 500000 * FROM dbo.OrderHistory WHERE OrderDate < (SELECT '19961029');
(Og ja, jeg er klar over, at jeg overtræder mine egne regler og bruger SELECT *
og TOP
uden ORDER BY
, men for enkelhedens skyld prøver jeg mit bedste for at minimere min indflydelse på optimeringsværktøjet.)
Resultater:
(500000 række(r) påvirket)Tabel 'Ordrehistorik'. Scanningsantal 1, logisk læser 23, fysisk læser 0, read-ahead læser 0, lob logisk læser 0, lob fysisk læser 0, lob read-ahead læser 0.
Vi returnerer 500.000 rækker, og det tager omkring 10 sekunder. Jeg ved med det samme, at der er noget galt med det logiske læsenummer. Selvom jeg ikke allerede kendte til de underliggende data, kan jeg se fra gitterresultaterne i Management Studio, at dette trækker mere end 23 sider med data, uanset om de er fra hukommelsen eller cache, og dette burde afspejles et sted i STATISTICS IO
. Ser på planen...
...vi ser, at der er parallelitet derinde, og at vi har scannet hele bordet. Så hvordan er det muligt, at der kun er 23 logiske læsninger?
En anden "identisk" forespørgsel
Et af mine første spørgsmål tilbage til Steve var:"Hvad sker der, hvis du fjerner parallelisme?" Så jeg prøvede det. Jeg tog den originale underforespørgselsversion og tilføjede MAXDOP 1
:
SET STATISTICS IO ON; SELECT TOP 500000 * FROM dbo.OrderHistory WHERE OrderDate < (SELECT '19961029') OPTION (MAXDOP 1);
Resultater og plan:
(500000 række(r) påvirket)Tabel 'Ordrehistorik'. Scanningsantal 1, logisk læser 149589, fysisk læser 0, read-ahead læser 0, lob logisk læser 0, lob fysisk læser 0, lob read-ahead læser 0.
Vi har en lidt mindre kompleks plan, og uden paralleliteten (af indlysende grunde), STATISTICS IO
viser os meget mere troværdige tal for logiske læsetællinger.
Hvad er sandheden?
Det er ikke svært at se, at en af disse forespørgsler ikke fortæller hele sandheden. Mens STATISTICS IO
fortæller os måske ikke hele historien, måske spor vil. Hvis vi henter runtime-metrics ved at generere en faktisk eksekveringsplan i Plan Explorer, ser vi, at den magiske lavlæst-forespørgsel i virkeligheden trækker dataene fra hukommelsen eller disken og ikke fra en sky af magisk nissestøv. Faktisk har den *flere* læsninger end den anden version:
Så det er tydeligt, at læsninger sker, de vises bare ikke korrekt i STATISTICS IO
output.
Hvad er problemet?
Nå, jeg skal være helt ærlig:Jeg ved det ikke, bortset fra det faktum, at parallelisme helt sikkert spiller en rolle, og det ser ud til at være en slags racetilstand. STATISTICS IO
(og da det er der, vi får dataene, viser vores Tabel I/O-faneblad) et meget misvisende antal læsninger. Det er tydeligt, at forespørgslen returnerer alle de data, vi leder efter, og det fremgår tydeligt af sporingsresultaterne, at den bruger læsninger og ikke osmose til at gøre det. Jeg spurgte Paul White (blog | @SQL_Kiwi) om det, og han foreslog, at kun nogle af pre-thread I/O-tællingerne er inkluderet i totalen (og er enig i, at dette er en fejl).
Hvis du vil prøve dette af derhjemme, er alt hvad du behøver, AdventureWorks (dette bør repro mod 2008, 2008 R2 og 2012 versioner), og følgende forespørgsel:
SET STATISTICS IO ON; DBCC SETCPUWEIGHT(1000) WITH NO_INFOMSGS; GO SELECT TOP (15000) * FROM Sales.SalesOrderHeader WHERE OrderDate < (SELECT '20080101'); SELECT TOP (15000) * FROM Sales.SalesOrderHeader WHERE OrderDate < (SELECT '20080101') OPTION (MAXDOP 1); DBCC SETCPUWEIGHT(1) WITH NO_INFOMSGS;
(Bemærk, at SETCPUWEIGHT
bruges kun til at lokke parallelisme. For mere information, se Paul Whites blogindlæg om Plan Costing.)
Resultater:
Tabel 'SalesOrderHeader'. Scantæller 1, logisk læser 4, fysisk læser 0, read-ahead læser 0, lob logisk læser 0, lob fysisk læser 0, lob read-ahead læser 0.Tabel 'SalesOrderHeader'. Scanningsantal 1, logisk læser 333, fysisk læser 0, read-ahead læser 0, lob logisk læser 0, lob fysisk læser 0, lob read-ahead læser 0.
Paul påpegede en endnu enklere repro:
SET STATISTICS IO ON; GO SELECT TOP (15000) * FROM Production.TransactionHistory WHERE TransactionDate < (SELECT '20080101') OPTION (QUERYTRACEON 8649, MAXDOP 4); SELECT TOP (15000) * FROM Production.TransactionHistory AS th WHERE TransactionDate < (SELECT '20080101');
Resultater:
Tabel 'Transaktionshistorik'. Scanningsantal 1, logisk læser 5, fysisk læser 0, read-ahead læser 0, lob logisk læser 0, lob fysisk læser 0, lob read-ahead læser 0.Tabel 'TransactionHistory'. Scanningsantal 1, logisk læser 110, fysisk læser 0, read-ahead læser 0, lob logisk læser 0, lob fysisk læser 0, lob read-ahead læser 0.
Så det ser ud til, at vi nemt kan reproducere dette efter behag med en TOP
operatør og en lav nok DOP. Jeg har indgivet en fejl:
- STATISTIK IO underrapporterer logiske læsninger for parallelle planer
Og Paul har indgivet to andre noget relaterede fejl, der involverer parallelisme, den første som et resultat af vores samtale:
- Kardinalitetsvurderingsfejl med pushet prædikat på et opslag [ relateret blogindlæg ]
- Dårlig ydeevne med parallelisme og Top [ relateret blogindlæg ]
(For nostalgikere er her seks andre parallelitetsfejl, jeg påpegede for et par år siden.)
Hvad er lektien?
Vær forsigtig med at stole på en enkelt kilde. Hvis du udelukkende ser på STATISTICS IO
efter at have ændret en forespørgsel som denne, kan du blive fristet til at fokusere på det mirakuløse fald i læsninger i stedet for stigningen i varighed. På hvilket tidspunkt kan du klappe dig selv på skulderen, forlade arbejdet tidligt og nyde din weekend, og tro at du lige har haft en enorm præstationsindvirkning på din forespørgsel. Når selvfølgelig intet kunne være længere fra sandheden.