Again, this is another one of those little bits of functionality that has been present since year dot. Unfortunately, it seems to be forgotten by many in the great game of query investigation.
Being able to see the IO patterns of a query that we're running to help us see where the heavy lifting is occurring is really useful in allowing us to get the bottom of problems quickly, or see the benefits of our tuning efforts (or otherwise!).
Its easy to do so with the following TSQL.
SET STATISTICS TIME,IO ONYou can separate these and only have one of the options, but i've never felt the need to do so.
For the forgetful (or lazy) amongst us, we can just set this in SSMS options.
So Tools > Options > Query Execution > SQL Server > Advanced.
Simply tick SET STATISTICS TIME and SET STATISTICS IO on. Sorted.
It's off to work we go...
So lets run a query, I have an old copy of AdventureWorksDW2019 lying around, so i'll use that. Don't worry about what the query is doing, we just want some output.
SELECT EnglishProductCategoryName [Product Category], COUNT(EnglishProductName) AS [No. of Products in Category]
FROM DimProductCategory C
INNER JOIN(SELECT EnglishProductName, ProductCategoryKey
FROM DimProduct P
INNER JOIN DimProductSubcategory S
ON P.ProductSubcategoryKey = S.ProductSubcategoryKey) P
ON C.ProductCategoryKey = P.ProductCategoryKey
GROUP BY EnglishProductCategoryName;
Data, great.... but we're not interested in that so click the Messages tab.
Oh my... look at all of this.
This gives us the breakdown of the different IO access totals for each table, AND the total query duration, the CPU usage. Oh, AND the parse/compile times as well.
Lets take a closer look, what does this information mean?
SQL Server parse and compile time
How long, and how much CPU it took to compile the query. If you have really complicated queries, take a look here to see how much effort it takes SQL to even create a plan. This shouldn't ever be underestimated, the more complex queries become, the longer they can take to even generate a plan in the first place. If you have code that has high Parse and Compile times AND is recompiled often (for whatever reason), then consider splitting the code out into smaller pieces. In the worst case situations, a load of fat queries all generating plans can lead to a starvation of compile memory available, and you'll start to recieve RESOURCE_SEMPHORE_QUERY_COMPILE waits. Not nice.
Now, some IO stats:
Table
Name of the table. Great, we all sussed that one out, thanks.
Scan count
Number of seeks or scans started after reaching the leaf level.
Scan count is 0 if the index used is a unique index or clustered index on a primary key and you're seeking for only one value.
Scan count is 1 when you're searching for one value using a non-unique clustered index defined on a non-primary key column. This process is done to check for duplicate values for the key value that you're searching for.
Scan count is N when N is the number of different seeks or scans started towards the left or right side at the leaf level after locating a key value using the index key. Lookup operators may cause this number to be high.
Consider the following predicate...
WHERE Index_Key_Column = <value>.If the index was unique (or clustered PK ), scan count would be 0.
However, if the index was clustered and not unique, then the scan count would be 1 for each different seek or scan performed.
The reduction in scan counts is another reason to make your indexes unique if the data is such, it essentially allows SQL to avoid work.
Logical reads
Number of pages read from the data buffer. - Better, as at least its in memory already.
Physical reads
Number of pages read from disk. - Ouch, these may hurt performance. Spinny disks means more ouch.
Read-ahead reads
Number of pages placed into the cache for the query. This is where SQL is trying to help, it sees the query, and thinks "Ah, I know, these data values are going to be needed in advance, so i'll guess and try and read them into memory beforehand". Great, thanks for that, but i'd like them in memory already please.
Lob logical reads
Number of pages read from memory. What, Again?? Ah, but these are the "off page" data rows, so text, ntext, image, varchar(max), nvarchar(max), varbinary(max), AND columnstore index pages. Note, this is primarily where the heavy lifting of your columnstore indexes shows up.
Lob physical reads
As Physical Reads above, but again for off page/columnstore data .
Lob read-ahead reads
As Read-Ahead Reads above, but again for off page/columnstore data .
WorkTables/WorkFiles
You may see these in your output if Tempdb was involved in the execution of your query.
Sometimes, this may be due to the presence of particular keywords, ie... things like
GROUP BY, UNION or even ORDER BY. Work for Spool operators inside the plan will also show here. If the Logical reads are low/zero then its not the end of the world, but high numbers here may impact performance. I've also seen partition scans cause worktables to appear also.
The Tables/Files differentiates the type of structure within Tempdb.
Additional Columnstore information.
Not shown here, but for columnstore indexes, there will be an additional line, stating Segment Reads, and Segments skipped. This is showing how much segment elimination SQL was able to perform so that it doesn't have to read the data. More segments skipped is better.
So that gives us 7 main little person metrics.
But the output is verbose text, it's difficult to read easily, prepare and compare?
This is where the Master developer Richie Rump Esq. (blog | twitter) has got your back. He developed a simple webpage where you can just copy in the Statistics Time and IO output on to a page, click a button, and its all tabulated for you an instant later. Marvellous stuff.
Simply paste your statistics IO / Time data in, and click Parse
And...voila!
Each query broken down into a separate table, AND a totals table at the end. You can then just copy this straight out into Excel or anywhere else you fancy. Always check the results though, as i've seen Columnstore values missed, and double counting of CPU values from the actual output.
But Wait! We have a new Challenger!
I found this whilst I was waiting to publish this blog post, and I think it could be a little dwarfish gem from Greg over at: https://twitter.com/GFunkEraApps . This one does have a donation fee attached to it, but that is what you decide that you want to donate. I payed $5 through Paypal as i'm inherently tight.
This is an extension for SSMS, so when you have statistics IO/TIME turned on, then you automatically get additional tabs inside SSMS, so don't even have to copy the results out.
Allow me to demonstrate such wicked witchcraft.
Just running a query on a copy of AdventureWorksDW
You now have the 2 additional tabs below:
Base Report
Statistics Report
I'll start with the Statistics Report...this is your formatted Stats IO and Time data, AND a percentage breakdown of the logical reads for a fast view of the heaviest tables. Nice.
Base Report?
Note, that 'Set as base report' button at the top. What's that all about then? By clicking that, it tells SSMS that these are you baseline output figures to compare against for future runs.
The Base Report tab is populated with your original Stats IO data, but by running the query again when you have a base report set (you know, after you've added that blindingly obvious index that was missed), the Statistics Report tab now shows something like:
All colour coded for easy viewing, and I like colours.
And there we have it. Its a simple stalwart bit of functionality that seems to get forgotten more often than it deserves to be. When combined with Mr. Rump's or Greg's fine work (give them both some love, as its toolsets like these that make our lives so much easier), the data can be easily dissected too. Lovely.
Thanks for reading.
Rod White, protector of short people.
Title image courtesy of https://www.disneyclips.com/images4/snowwhite-grumpy.html
Nice article, thanks!