SQL Server Stored Procedures – Execution Time Analysis

execution-plansql serverstored-procedures

I have a stored procedure and several statements in it. The below is execution time statistics of the procedure:

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

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

(1 row(s) affected)

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

(29 row(s) affected)

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

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

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

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

(1 row(s) affected)

SQL Server Execution Times: 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 Execution Times: CPU time = 11484 ms, elapsed time =
2283 ms.

As you can see the total of 4562 ms. But when I look at the status bar I see that it took 2 seconds. I expect that it should be 4 seconds. Why are these two different?

enter image description here

Best Answer

This happens because SET STATISTICS TIME ON will give you summarized time results for a stored procedure in addition to time results for each query that's part of the stored procedure. Let's run a simple test to try to reproduce what you saw. The following code isn't important except that it runs for a few seconds on my machine:

set statistics time on;

WITH E00(N) AS (SELECT 1 UNION ALL SELECT 1),
        E02(N) AS (SELECT 1 FROM E00 a, E00 b),
        E04(N) AS (SELECT 1 FROM E02 a, E02 b),
        E08(N) AS (SELECT 1 FROM E04 a, E04 b),
        E16(N) AS (SELECT 1 FROM E08 a, E08 b),
        E32(N) AS (SELECT 1 FROM E16 a, E16 b),
   cteTally(N) AS (SELECT ROW_NUMBER() OVER (ORDER BY N) FROM E32)
SELECT AVG(CAST(N AS BIGINT)) 
FROM cteTally
WHERE N <= 10000000;

WITH E00(N) AS (SELECT 1 UNION ALL SELECT 1),
        E02(N) AS (SELECT 1 FROM E00 a, E00 b),
        E04(N) AS (SELECT 1 FROM E02 a, E02 b),
        E08(N) AS (SELECT 1 FROM E04 a, E04 b),
        E16(N) AS (SELECT 1 FROM E08 a, E08 b),
        E32(N) AS (SELECT 1 FROM E16 a, E16 b),
   cteTally(N) AS (SELECT ROW_NUMBER() OVER (ORDER BY N) FROM E32)
SELECT AVG(CAST(N AS BIGINT)) 
FROM cteTally
WHERE N <= 1000000;

Abbreviated output from SET STATISTICS TIME ON:

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

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

As expected, there are two separate measurements for the execution time with the second query running in about one tenth of the time of the first. Now I'll create and run a stored procedure that just calls the above code. Abbreviated output from SET STATISTICS TIME ON:

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

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

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

The math works out for my simple example: 1187 + 110 = 1297 CPU time and 1201 + 117 = 1319 elapsed time.

Related Question