Don’t even believe SSMS when you think it’s telling the truth

This is in follow up to my last post How to make sure you see the truth in Management Studio which explained that the time that you see at the bottom of a Management Studio window cannot be believed to represent the time it takes for a query to execute as it also includes the time taken for SSMS to receive and format the data grid.

Now, very soon after that went live I received a comment from Dave Ballantyne (Blog | Twitter) mentioning that having SET STATISTICS TIME ON affects the time TSQL takes to execute. Really? That sounds dumb. Not Dave’s comment, but the fact that the turning on of a setting to collect statistics actually affect the statistics you are collecting. That’s a bit like timing the 100m by making the runners carry a guy with a stopwatch on their backs. Dave actually blogged about it here – The Observer Effect In Action and after reading that I started thinking about how much effect the TIME ON setting was having.

Now you can wrap a piece of code with a few lines of other code and easily come up with a way of measuring the time taken. Declare a variable to hold the time, set it to GETDATE(), run your script, subtract the time now from the variable …

StatisticsTimeOn01_thumb.png

So, if I wrap the execution of the UDF and TVF from my previous post in this code and execute it twice, once with TIME ON and once with TIME OFF I’ll see the difference that this causes.

StatisticsTimeOn02_Query_thumb.png

The scalar UDF wrapped in the Start/Stop timing code twice – once for TIME ON and once for TIME OFF 

So running this I thought I might see a few ms difference as SQL Server takes a CPU cycle or two to log the time taken.

WRONG!
StatisticsTimeOn03_Results_thumb.png

Over 2s is added to the execution time of the Scalar UDF when you have STATISTICS TIME ON.

OK, what about the TVF? That only took 3/10ths of a second in my last test, how would this be affected? I re-wrote the script to use the TVF and return the times as above and the results were pretty variable, sometimes TIME ON was quicker, sometimes TIME OFF was quicker, only ever by a few ms though. This was intriguing, and annoying. SQL Server was skewing my results without so much as a mention in Books OnLine that it might happen.

Having seen the TVF results vary I set about running these queries a lot of times and seeing how much things did actually vary. This is the resulting code:

I left this run for almost an hour on my home machine and the results are quite interesting
SummaryResults_thumb.png

Of the 199 executions the TVF averaged 8ms faster execution with TIME ON whereas the Scalar UDF over the same number of executions was on average 2.6s faster with TIME OFF.

So what does this mean?
To be honest, other than advising people to not use SET STATISTICS TIME as an absolute measure of their query execution times, I don’t know. I can find no details online about why this is the case or any way to mitigate it other than, as Dave suggested, using variables in the way I have above. It seems an arbitrary ‘weight’ that comes along when Scalar UDF’s are involved, it does even scale with the number of rows returned.