How to make sure you see the truth with Management Studio

LiveJournal Tags: TSQL,How To,SSMS,Tips and Tricks

Did you know that SQL Server Management Studio can mislead you with how your code is performing?

I found a query that was using a scalar function to return a date and wanted to take the opportunity to remove it in favour of a table valued function that would be more efficient. The original function was simply returning the start date of the current financial year. The code we were using was:

Pretty easy stuff, and pretty quick but this function gets called from dozens of places thousands of times a day so any saving here could have a big effect on our systems. I dived in and created an alternative to this function so that I could test if the new version was quicker. I created this:

Good, now I could see which was faster. As they both complete in less than 1s I used  – I ran SET STATISTICS TIME ON and then executed both functions with:

The results were inconclusive though:

SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 0 ms.
(1 row(s) affected)

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 1 ms.
(1 row(s) affected)

Even running the lots of times, there was nothing to separate them.

OK, easily resolved, I’ll join them to a big table and see my TVF whoop some scalar butt … I have a Numbers table in the test database so I adapted the above query to be

The results from this shocked me
SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
(1000 row(s) affected)

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 9 ms.
1 done ————————————–

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
(1000 row(s) affected)

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 56 ms.
2 done—————————————

The TVF was slower? No way. I’m not having that, I altered the ROWCOUNT

100,000 rows 1,000,000 rows

SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 21 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
(100000 row(s) affected)

SQL Server Execution Times:
   CPU time = 561 ms,  elapsed time = 1335 ms.
1 done ————————-

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
(100000 row(s) affected)

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 1180 ms.
2 done————————–

SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 2 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
(1000000 row(s) affected)

SQL Server Execution Times:
   CPU time = 6879 ms,  elapsed time = 9739 ms.
1 done ————————-

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
(1000000 row(s) affected)

SQL Server Execution Times:
   CPU time = 359 ms,  elapsed time = 8478 ms.
2 done————————-

This is crazy, the scalar function is still faster?

No, it isn’t

Management Studio is causing the results to be skewed because it is doing what I have asked it. I asked to see 2M rows of data(1M from each function) and getting that to my screen in a pretty fashion takes some time. What I need to do is remove the presentation of the data from the process so that I can see simply how fast the functions can do their work. To do this, create a variable for each column that you have in your query and simply collect the values into those variables …

Now we see the true difference between a Scalar and Table Functions
SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 28 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.

SQL Server Execution Times:
   CPU time = 6162 ms,  elapsed time = 7188 ms.
1 done ————————————–

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 1 ms.

SQL Server Execution Times:
   CPU time = 327 ms,  elapsed time = 320 ms.
2 done—————————————
 

Yep, now the scalar function takes over 7s to complete when it used to take 9.7s when we had the data come to the results grid but the TVF completes a million rows in a staggering 320ms, down from 8.4s when we had the grid of data too.

So what have we learned?
If you are working with Management Studio you HAVE to understand that the results you see are for the whole process to complete, including the rendering of the data to your screen. My tests were done on a local SQL Instance, if it was over a LAN then the results would have pulled a million rows of data across the network, slowing all other traffic accordingly.