SQL Server查询性能测试结果解读：多执行时间相关疑问

问题背景 #

我在项目中用SQL Server Management Studio测试特定存储过程的运行耗时，测试代码如下：

SET STATISTICS TIME ON

SET STATISTICS IO ON
EXEC <my stored procedure>

SET STATISTICS IO OFF
SET STATISTICS TIME OFF

但无法理解输出结果：

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms. 
SQL Server parse and compile time: 
   CPU time = 21 ms, elapsed time = 21 ms.

 SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product_loadtable'. Scan count 1, logical reads 942, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product_option'. Scan count 2, logical reads 26, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product_description'. Scan count 157, logical reads 628, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'barsizes'. Scan count 0, logical reads 314, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product_detail'. Scan count 1, logical reads 17, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product'. Scan count 1588, logical reads 6299, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'inventory'. Scan count 1, logical reads 24, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'option_value'. Scan count 1, logical reads 3, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.

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

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

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

Completion time: 2023-04-21T09:49:57.7878903-04:00

我的疑问：

• 为何会出现多个SQL Execution Times？
• 这些时间是否需要累加？
• 能否将所有时间合并为一个易读的总时间？
• 我的操作是否存在错误？

解答 #

1. 多个SQL Execution Times的原因 #

出现多条统计是正常现象，主要有几个原因：

• 存储过程内部包含多个独立执行批次/语句，每个语句执行完成后，SQL Server都会输出该语句的执行时间统计。
• SET STATISTICS TIME ON/OFF这类开关语句本身也会触发一次执行时间统计，这些语句耗时极短，所以会出现CPU time = 0 ms, elapsed time = 0 ms的空统计行。
• 单独的SQL Server parse and compile time是存储过程的编译耗时统计，和执行阶段的统计分开输出。

2. 时间是否需要累加 #

要分两种时间类型来看：

• CPU时间：可以累加所有非0的CPU时间值（比如你的输出里是21ms编译CPU + 31ms执行CPU = 52ms总CPU消耗）。因为SQL Server可能用多线程执行，CPU时间总和可能大于实际流逝时间（elapsed time）。
• Elapsed时间：是从语句开始到结束的实际墙钟时间，不能累加。你需要关注的是最后一个非0的elapsed时间（比如你的输出里的62ms），或者取所有统计中最大的elapsed值，这是存储过程整体执行的大致耗时。

3. 合并为易读总时间的方法 #

• 手动汇总：把所有非0的CPU时间相加，取最大的elapsed时间作为总耗时参考。
• 用更精准的工具：比如在SSMS中开启包括实际执行计划（Ctrl+M），执行计划的“执行统计”里会有汇总的执行时间；或者用sys.dm_exec_query_stats动态管理视图查询存储过程的总执行耗时。
• 简单脚本捕获：可以在执行前后记录时间，比如：

DECLARE @StartTime DATETIME = GETDATE()
EXEC <my stored procedure>
SELECT DATEDIFF(ms, @StartTime, GETDATE()) AS '总耗时(ms)'

这种方法得到的是整体流逝时间，适合快速查看总耗时。

4. 操作是否错误 #

你的操作没有问题，SET STATISTICS TIME和SET STATISTICS IO的用法是标准的性能测试方式，出现多条统计输出是SQL Server的正常行为，不用修改操作方式。

内容的提问来源于stack exchange，提问作者duerzd696