This is a quick post regarding a couple of things I found someone doing the other day when using Profiler and SSMS to tune one of his queries. Basically he was getting frustrated because he had been making changes to his code which he believed would speed up his query and yet he wasn’t getting anything consistent out of either SSMS or Profiler to prove this.
As it turned out, his understanding of what to monitor was very wrong as he was only using Profiler to look at Duration and likewise relying on the “timer” in SSMS to validate his results. This is not the best way to do things as these both have quite major limitations when used in this type of scenario.
The best indicators we can really use are CPU, Reads, and Writes.
If we take a very simple query using the AdventureWorks2012 database, we can get some base data for CPU, Reads, Writes, and Duration for a simple query using both SSMS and Profiler:
set statistics time on
It’s clear to see that here we have a quick query for which all our stats look good and roughly correct. So far, so good.
However, what I’m going to do now is head to another query window and run the following:
set ModifiedDate = ModifiedDate
Now, run the first query again and, as you know, it will wait due to the lock that the update has on the sales.salesOrderDetail table.
Go and rollback the transaction in the other window and your SELECT will complete.
So now let’s look at the results from our SELECT statement… well, the first thing to notice is that both Duration figures are huge.
Why is this?
Well this is because both Profiler and SSMS will keep counting from the moment you press EXECUTE, to the moment the last row is returned to the SSMS grid. This could, depending on the workload on your test server, mean that you get very inconsistent results for Duration when tuning your code.
However, as you’ve seen, the results for CPU, Reads, and Writes hardly vary at all and therefore they are the values you really should be keeping an eye on.
One last thing to remember is a key part I mentioned above… “to the moment the last row is returned to the SSMS grid”. This is vital to remember as if your query returns, for example, 1 billion rows, then you will probably find that the query itself was finished within a couple of seconds, but the time taken to process that data in SSMS was in the minutes. Again, this means that watching the Duration value may give you very inaccurate results.
If you wish to know the true speed (well, as close to true as we can get) of your queries, consider turning off the Grid option in SSMS.
Let’s make a query which will return a large grid:
from sales.SalesOrderDetail s
join sales.SalesOrderDetail s1
on s.SalesOrderDetailID = s1.SalesOrderDetailID
join sales.SalesOrderDetail s2
on s.SalesOrderDetailID = s2.SalesOrderDetailID
join sales.SalesOrderDetail s3
on s.SalesOrderDetailID = s3.SalesOrderDetailID
join sales.SalesOrderDetail s4
on s.SalesOrderDetailID = s4.SalesOrderDetailID
As you can see, this query actually finished returning in 8 seconds on my test machine.
So… what was the true duration of the query? Well, let’s disable our grid in SSMS…
Click Query -> Query Options…
And then on the left click Grid, and check the “Discard the results after execution” box
This means that SSMS will not go through the row by row processing but simply tell you when SQL Server stopped streaming the results. Ie. When the query actually finished.
Let’s run our same query again and see what we get.
As you can see, the true speed of the query was actually just 3 seconds. The grid (on my machine which doesn’t render quickly) was actually inflating the cost of my query quite substantially. Therefore if I was to tune this query and see a reduction from 8 to 7 seconds I may not be pleased, but from 3 to 2 seconds would be a fantastic result. Therefore I recommend that once you’re happy with the output, you test the actual query speed without a grid just to see what a difference you have made with your tuning.