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.
