HiveBrain v1.2.0
Get Started
← Back to all entries
patternsqlMinor

SET STATISTICS TIME ON elapsed time is different than actual execution time

Submitted by: @import:stackexchange-dba··
0
Viewed 0 times
elapsedactualthantimedifferentexecutionstatisticsset

Problem

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?

Solution

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 be

Code Snippets

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
-- 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;
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;
SELECT  TOP 100000 *
INTO    #t_Test2
FROM    sys.all_objects sao1;
DROP TABLE #t_Test;

Context

StackExchange Database Administrators Q#154611, answer score: 6

Revisions (0)

No revisions yet.