3

I have a stored procedure which I'm running while using SET STATISTICS TIME ON, and overall the execution time of the procedure is 31 seconds, but when looking at the information from STATISTICS TIME, the result of adding up all of the elapsed times for each query is greater than 31 seconds.

For example:

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

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

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

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

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

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

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

I feel like I'm getting things mixed up while trying to read the information here, since the execution time of the query definitely isn't 85452 ms.

Also, I know that if the CPU time is greater than the elapsed time then the query went parallel, and even when double-checking this on the actual execution plan, there aren't any parallel operations executed.

So, why is the elapsed time in STATISTICS TIME different from the actual execution time of a query?

5

The SET STATISTICS options will report the statistics for each statement, which when coupled with procedures can lead to including what are effectively "summary" results - as the call to the procedure itself resolves, an additional statistics record will be returned containing the statistics for the procedure itself.

This can lead to multiple "summary" results if a procedure does something like call another procedure.

To illustrate when the SET STATISTICS options return information, we can create up a couple of procedures, one of which that is simply going to call the other.

USE tempdb;
GO

IF ( OBJECT_ID( 'dbo.TestProc', 'P' ) IS NULL )
BEGIN
    EXEC( 'CREATE PROCEDURE dbo.TestProc AS SET NOCOUNT ON;' );
END;
GO

ALTER PROCEDURE dbo.TestProc
AS BEGIN
    -- SET NOCOUNT ON; -- Excluded to reduce noise for the example;
    SELECT  TOP 100000 sao1.*
    INTO    #t_Test
    FROM    sys.all_objects sao1
    CROSS APPLY sys.all_objects sao2;       

    SELECT  TOP 100000 *
    INTO    #t_Test2
    FROM    sys.all_objects sao1;

    DROP TABLE #t_Test;
    DROP TABLE #t_Test2;
END;
GO

IF ( OBJECT_ID( 'dbo.TestSuperProc', 'P' ) IS NULL )
BEGIN
    EXEC( 'CREATE PROCEDURE dbo.TestSuperProc AS SET NOCOUNT ON;' );
END;
GO

ALTER PROCEDURE dbo.TestSuperProc
AS BEGIN
    -- SET NOCOUNT ON; -- Excluded to reduce noise for the example;
    EXECUTE dbo.TestProc;
END;
GO

With these procedures in place, let's turn STATISTICS TIME on and run the operations performed by executing either procedure without actually calling one:

-- Just procedure contents;
SET NOCOUNT ON;
SET STATISTICS TIME ON;
SELECT  TOP 100000 sao1.*
INTO    #t_Test
FROM    sys.all_objects sao1
CROSS APPLY sys.all_objects sao2;       

SELECT  TOP 100000 *
INTO    #t_Test2
FROM    sys.all_objects sao1;

DROP TABLE #t_Test;
DROP TABLE #t_Test2;
SET NOCOUNT OFF;
SET STATISTICS TIME OFF;

The output will look a little bit like this:

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

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

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

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

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

Matching this all up looks as would be expected:

SET NOCOUNT ON;
SET STATISTICS TIME ON;
-- Statistics will now start being reported;
SELECT  TOP 100000 sao1.*
INTO    #t_Test
FROM    sys.all_objects sao1
CROSS APPLY sys.all_objects sao2;       

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

SELECT  TOP 100000 *
INTO    #t_Test2
FROM    sys.all_objects sao1;

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

DROP TABLE #t_Test;

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

DROP TABLE #t_Test2;

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

SET NOCOUNT OFF;

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

-- Statistics will now stop being reported;
SET STATISTICS TIME OFF;

Four statements ( SELECT, SELECT, DROP, DROP ) plus a SET NOCOUNT OFF; for a fifth statement, five messages from STATISTICS TIME.

However, if we were to capture the statistics by running the procedure:

-- Procedure statistics;
SET NOCOUNT ON;
SET STATISTICS TIME ON;
EXECUTE dbo.TestProc;
SET NOCOUNT OFF;
SET STATISTICS TIME OFF;
 SQL Server Execution Times:
   CPU time = 140 ms,  elapsed time = 488 ms.

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

 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 = 187 ms,  elapsed time = 529 ms.

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

Suddenly, a sixth message is returned - this is a message indicating the total statistics for the procedure itself, and is the sum of the statements contained within the procedure. We can generate a seventh summary record in the results of STATISTICS TIME by executing the dbo.TestSuperProc we created:

-- Super Proc statistics;
SET NOCOUNT ON;
SET STATISTICS TIME ON;
EXECUTE dbo.TestSuperProc;
SET NOCOUNT OFF;
SET STATISTICS TIME OFF;
 SQL Server Execution Times:
   CPU time = 187 ms,  elapsed time = 259 ms.

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

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

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

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

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

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

In effect, your second last message ( likely before a SET NOCOUNT OFF as in my example ) is reporting the 31 seconds you are expecting - the total CPU and elapsed time for the calling procedure. As you seem to be aware, CPU time is really where you want to pay attention for performance tuning, as it can be higher than the elapsed time if the query goes parallel, or lower if the procedure spends time sleeping on wait signals and I/O operations.

2

I would recommend using SET STATISTICS IO ON if you want to measure the cost of a query. It will show read / write times which gives you a better cost understanding of your query, plus it will measure the outcome if you make changes to the query for performance testing.

CPU time refers to the actual time spend on CPU where as the elapsed time is the total time to complete the execution which includes signal wait time, wait time to complete the IO operation and time taken to transfer the output to the client. Waits can add time on this number which will show different than actual execution time.

  • I agree with what you're saying and I am mostly using STATISTICS IO when performing tuning, but this time I also wanted to see the breakdown per time of the query and am wondering why/how is STATS TIME showing what it is. – Radu Gheorghiu Nov 8 '16 at 16:28
  • CPU time refers to the actual time spend on CPU where as the elapsed time is the total time to complete the execution which includes signal wait time, wait time to complete the IO operation and time taken to transfer the output to the client. Waits can add time on this number which will show different than actual execution time. – bwilliamson Nov 8 '16 at 16:29

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.