patternsqlMinor
SET STATISTICS TIME ON elapsed time is different than actual execution time
Viewed 0 times
elapsedactualthantimedifferentexecutionstatisticsset
Problem
I have a stored procedure which I'm running while using
For example:
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
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
This can lead to multiple "summary" results if a procedure does something like call another procedure.
To illustrate when the
With these procedures in place, let's turn
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:
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.
Four statements (
However, if we were to capture the statistics by running the procedure:
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
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
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;
GOWith 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.