Question about Time Statistics, Execution Plan and "print"

Question

In trying to determine what area of a large query i have is causing performance problems i took three steps. Including the execution plan, setting time statistics to on and printing immediately before and after sections that i believe might cause a problem. Example:

print '1'
SELECT ID FROM Test
print '2'

When i look at my execution plan it says that a certain section is taking up a large percentage of the "cost". When I compare this percentage to the elapsed time between my print '1' and print '2' it's seems like there is no way that percentage is even close.

Is it a safe bet to rely on the printed values and the time statistics over the estimated cost? If it is, would it make sense for me to focus on areas that have a large elapsed time between printed values rather than the estimated costs?

Answer 1

It's not a safe bet, because PRINT statements are buffered up for output - they're not immediate. The execution plan is a good place to be looking for performance problems as it will identify where the costliest parts are and help identify things like missing indexes (e.g. if you see table scans).

You should also really use SQL Profiler - monitor SQL:StmtStarting and SQL:StmtCompleted events - that will show you stats for how long each statement takes to execute (StmtCompleted is the main one you're interested in).

Answer 2

If you only print '1' and print '2' then measure the time between when you see the message in your SSMS messages pane then you are falling victim of output buffering between the server and the client. The print '1' may not immediately sent back to the client, and SqlClient, ADO.Net and SSMS also do some buffering of their own. So overall you may see the '1' in your SSMS results Messages panel way, way later than it actually occured. Much better is to print the time from getdate(), not just '1'. This way you take out the buffering from the equation and you can see in the message itself the time when the server executed the 'print', not the time when its output was displayed by SSMS.

SET STATISTICS TIME ON will always be more accurate, but is sometimes difficult to understant to which statement exactly it reffers to.

What I usualy do is something like this:

declare @nowString varchar(100);
declare @start datetime, @end datetime, @rc int, @elapsed int;

set @start = getdate();

select many, fields 
from bigtable 
join manytables on condition = complex 
where matches = many
order by wacky sort;

set @rc = @@rowcount;
set @end = getdate();
set @elapsed = datediff(ms, @start, @end);
set @nowString = cast(varchar(100), getdate(), 14);
raiserror(N'%s: At select No 1. Selected %i rows in %i ms', 10, 1, %nowString, @rc, @elapsed);

set @start = getdate();
...next select here...