SQL Stored Procedure execution time mystery

Question

I'm trying to figure out why a SQL Server stored procedure is executing slowly, so I've put in some crude timers, like this:

Create Procedure DoStuff
As Begin

    Declare @Stopwatch datetime 
    Set @Stopwatch=GetDate()

    Print char(13) + 'Task A'
    /* Perform Task A */
    Print DateDiff(ms, @Stopwatch, GetDate()); Set @Stopwatch = GetDate()

    Print char(13) + 'Task B'
    /* Perform Task B */
    Print DateDiff(ms, @Stopwatch, GetDate()); Set @Stopwatch = GetDate()

    Print char(13) + 'Task C'
    -- Perform Task C
    Print DateDiff(ms, @Stopwatch, GetDate()); Set @Stopwatch = GetDate()

End

Exec DoStuff

I'm getting something like this:

Task A
0

Task B
80

Task C
100

So I would think the procedure would take 180 ms to execute. However, the procedure takes 3000+ ms to execute; in Client Statistics, I get

Client processing time: 12
Total execution time: 3105
Wait time on server replies: 3093

What accounts for the extra ~2800 ms?

Answer 1

It could be a block on the table, or a wait for resources for some reason.

You could look at the management utilities and see if there are locks or waits going on, which is based on what it is showing.

OR, it could be network communication for replies inbound and outbound communication to the SP as well.

Answer 2

Transactionality if you're executing it in SSMS is an uninformed guess. But you should look at the execution plan to learn more about the real cause. It could be a number of things.

http://msdn.microsoft.com/en-us/library/ms178071.aspx

Answer 3

It is a crude way to check the individual times. A better way would be to run a trace in SQL Profiler and monitor the SP:Completed and SP:StmtCompleted events.

SP:Completed is recorded when the sproc completes, giving the overall time.
SP:StmtCompleted is recorded when each statement within a sproc completes. So this will give you the times for each individual part of the sproc.

It'd be worth using this approach, rechecking the figures and then going from there.

Answer 4

Also try turning off the "Show Execution Plan" option if you turn it on. That really throws off your numbers for total execution time -- it can often lead to a very misleading result for total execution time.

Answer 5

I'll bet that your procedure is recompiling each time it is running, which is taking the time. give this a read: http://www.sql-server-performance.com/articles/per/optimizing_sp_recompiles_p1.aspx

Make @Stopwatch an input parameter and pass in GETDATE(), then pass it back out as an OUTPUT parameter. You can then print another two time intervals, the time from EXECUTE to actual run, and the time from RETURN until the caller has control again.