SET STATISTICS TIME ON 运行时间与实际执行时间不同

Question

我有一个在使用时正在运行的存储过程，SET STATISTICS TIME ON该过程的总体执行时间为 31 秒，但是在查看来自 的信息时STATISTICS TIME，将每个查询的所有经过时间相加的结果大于 31秒。

例如：

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.

我觉得我在尝试阅读这里的信息时把事情搞混了，因为查询的执行时间肯定不是 85452 毫秒。

另外，我知道如果 CPU 时间大于经过的时间，那么查询会并行执行，即使在实际执行计划中仔细检查，也不会执行任何并行操作。

那么，为什么经过的时间STATISTICS TIME与查询的实际执行时间不同呢？

Answer 1

这些SET STATISTICS选项将报告每个语句的统计信息，当与过程结合使用时，可以导致包括有效的“摘要”结果 - 随着对过程本身的调用解析，将返回一个额外的统计记录，其中包含过程本身的统计信息.

如果一个过程执行诸如调用另一个过程之类的操作，这可能会导致多个“摘要”结果。

为了说明SET STATISTICS选项何时返回信息，我们可以创建几个过程，其中一个只是调用另一个。

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

准备好这些过程后，让我们打开STATISTICS TIME并运行通过执行任一过程而执行的操作，而无需实际调用：

-- 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;

输出看起来有点像这样：

 SQL Server 执行时间：
   CPU 时间 = 171 毫秒，已用时间 = 305 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 47 毫秒，经过时间 = 40 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 0 毫秒，经过时间 = 2 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 0 ms，经过时间 = 8 ms。

 SQL Server 执行时间：
   CPU 时间 = 0 毫秒，经过时间 = 0 毫秒。

匹配这一切看起来正如预期的那样：

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 执行时间：CPU 时间 = 171 毫秒，已用时间 = 305 毫秒。

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

SQL Server 执行时间：CPU 时间 = 47 毫秒，已用时间 = 40 毫秒。

DROP TABLE #t_Test;

SQL Server 执行时间：CPU 时间 = 0 毫秒，已用时间 = 2 毫秒。

DROP TABLE #t_Test2;

SQL Server 执行时间：CPU 时间 = 0 毫秒，已用时间 = 8 毫秒。

SET NOCOUNT OFF;

SQL Server 执行时间：CPU 时间 = 0 毫秒，已用时间 = 0 毫秒。

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

四个语句 ( SELECT, SELECT, DROP, DROP) 加上SET NOCOUNT OFF;第五个语句的 a，来自STATISTICS TIME.

但是，如果我们要通过运行该过程来捕获统计信息：

-- Procedure statistics;
SET NOCOUNT ON;
SET STATISTICS TIME ON;
EXECUTE dbo.TestProc;
SET NOCOUNT OFF;
SET STATISTICS TIME OFF;

 SQL Server 执行时间：
   CPU 时间 = 140 毫秒，已用时间 = 488 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 47 毫秒，经过时间 = 40 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 0 毫秒，经过时间 = 1 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 0 毫秒，经过时间 = 0 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 187 毫秒，已用时间 = 529 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 0 毫秒，经过时间 = 0 毫秒。

突然，返回了第六条消息——这是一条指示过程本身的总统计信息的消息，并且是过程中包含的语句的总和。我们可以STATISTICS TIME通过执行dbo.TestSuperProc我们创建的结果在结果中生成第七条摘要记录：

-- Super Proc statistics;
SET NOCOUNT ON;
SET STATISTICS TIME ON;
EXECUTE dbo.TestSuperProc;
SET NOCOUNT OFF;
SET STATISTICS TIME OFF;

 SQL Server 执行时间：
   CPU 时间 = 187 毫秒，已用时间 = 259 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 0 毫秒，经过时间 = 42 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 0 毫秒，经过时间 = 4 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 0 毫秒，经过时间 = 0 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 187 毫秒，已用时间 = 307 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 187 毫秒，已用时间 = 307 毫秒。

 SQL Server 执行时间：
   CPU 时间 = 0 毫秒，经过时间 = 0 毫秒。

实际上，您的倒数第二条消息（可能SET NOCOUNT OFF在我的示例中的a 之前）报告了您期望的 31 秒 - 总 CPU 和调用过程所用的时间。正如您似乎知道的，CPU 时间确实是您要注意性能调优的地方，因为如果查询并行，它可能会高于经过的时间，或者如果过程花费时间在等待信号和 I/ O 操作。