SQLServer语句运行统计信息

对于SQL语句，其编译时间、执行时间、做了多少磁盘读等非常重要，它直接关系到SQL语句的执行效率。在SQLServer中，有下面三个开关，用于收集语句运行的统计信息。这些信息对分析问题很有价值。
Set statistics time on
Set statistics io on
Set statistics profile on

下面分别对这三条语句进行实例说明。

   1、Set statistics time on

请先来看看Set statistics time on会返回什么信息。先运行语句：
dbcc dropcleanbuffers
-- 清除buffer pool里的所有缓存的数据
dbcc freeproccache
go
-- 清除buffer pool里的所有缓存的执行计划
go
Set statistics time on
go
select distinct ProductID, UnitPrice
from dbo.SalesOrderDetail_test
where ProductID = 777
union
select ProductID, UnitPrice
from dbo.SalesOrderDetail_test
where ProductID = 777
go
Set statistics time off
go

除了结果集以外，SQL Server还会返回下面这两段信息。
SQL Server parse and compile time:
   CPU time = 15 ms, elapsed time = 36 ms.

(4 row(s) affected)

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

1．CPU Time

这个值的含义指的是在这一步，SQL Server所花的纯CPU时间是多少，也就是说，语句花了多少CPU资源。

2．elapsed Time

此值指这一步一共用了多少时间，也就是说，这是语句运行的时间长短。（add by zhj: 从进程的角度来看，很容易理解，elapsed Time = CPU Time + 非运行时间，这里的非运行时间主要包括阻塞态时间、就绪态时间等，具体的，要看操作系统中进程有哪几种非运行状态。从内存读取数据到CPU的时间貌似也是非运行时间吧）

有些动作会发生I/O操作、产生了I/O等待，或者是遇到阻塞、产生阻塞的等待，总之时间用掉了，但是没有用CPU资源，所以Elapsed Time比CPU Time长是很正常的。但是CPU Time是语句在所有CPU上的时间总和，如果语句使用了多颗CPU，而其他等待几乎没有，那么CPU Time大于Elapsed Time也是正常的。

3．SQL Server parse and compile time

这一步，就是语句的编译时间。由于语句运行之前清空了所有执行计划，SQL Server必须要对它编译。这里的编译时间就不为0了。由于编译主要是CPU的运算，所以一般CPU Time和Elapsed Time是差不多的。如果这里相差比较大，就有必要看看SQL Server在系统资源上有没有瓶颈。

这里它们一个是15毫秒，另一个是36毫秒。

4．SQL Server Execution Times

语句真正运行的时间。由于语句是第一次运行，SQL Server需要把数据从磁盘读到内存里，这里语句的运行发生了比较长的I/O等待。所以这里的CPU Time和Elapsed Time差别就很大了，一个是32毫秒，而另一个是767毫秒。

总的来讲，这条语句花了36 + 767= 803毫秒，其中CPU时间为15 + 32 = 47毫秒。语句的主要时间应该是都花在了I/O的等待上了。

现在再做一遍语句，但是不清除任何缓存。
Set statistics time on
go
select distinct ProductID, UnitPrice
from dbo.SalesOrderDetail_test
where ProductID = 776
union
select ProductID, UnitPrice
from dbo.SalesOrderDetail_test
where ProductID = 776
go

这次应该比上次快很多，输出时间统计信息是：
SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 1 ms.

(4 row(s) affected)

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

由于执行计划被重用，“SQL Server parse and compile time”CPU Time是0，Elapsed Time也仅是1，这里省下编译时间36– 1 = 15毫秒。

由于数据已经缓存在内存里，不需要从磁盘上读取，“SQL Server Execution Times”CPU Time是32，Elapsed Time这次和CPU Time非常接近，是41，这里省下运行时间767– 41= 726毫秒。

从这里可以再次看出，缓存对语句执行性能起着至关重要的作用。

为了不影响其他测试，请运行下面的语句关闭Set Statistics Time On。
Set statistics time off
Go

   2、Set statistics io on

       这个开关能够输出语句做的物理读和逻辑读的数目，对分析语句的复杂度有很重要的作用。

       还是以刚才那个查询为例。
       dbcc dropcleanbuffers
       go
       Set statistics io on
       go
       select distinct ProductID, UnitPrice
       from dbo.SalesOrderDetail_test
       where ProductID = 777
       go

它的返回是：
(4 row(s) affected)

Table 'SalesOrderDetail_test'. Scan count 1, logical reads 3024, physical reads 1, read-ahead reads 3038, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

各个输出的含义是：

Table：表的名称。这里的表就是SalesOrderDetail_test。

scan count：执行的扫描次数。按照执行计划，表格被Scan了几次。一般来讲大表Scan的次数越多越不好，唯一的例外是如果执行计划选择了并发运行，由多个Thread同时做一个表的读取，每个Thread读其中的一部分，但是这里会显示所有Thread的数目。也就是有几个Thread在并发做，就会有几个Scan。这时数目大一点没问题。

logical reads：从数据缓存读取的页数。页数越多，说明查询要访问的数据量就越大，内存消耗量越大，查询也就越昂贵。可以检查是否应该调整索引，减少扫描的次数，缩小扫描范围。

physical reads：从磁盘读取的页数。

read-ahead reads：为进行查询而预读入缓存的页数。

physical reads 和read-ahead reads就是SQL Server为了完成这句查询而从磁盘上读取的页数。如果不为0，说明数据没有缓存在内存里，运行速度一定会受到影响。

lob logical reads：从数据缓存读取的Text、Ntext、Image或大值类型（Varchar(max)、Nvarchar(max)、Varbinary(max)）页的数目。

lob physical reads：从磁盘读取的Text、Ntext、Image或大值类型页的数目。

lob read-ahead reads：为进行查询而放入缓存的Text、Ntext、Image或大值类型页的数目。

然后再来运行一遍，不清空缓存。
Set statistics io on
go
select distinct ProductID, UnitPrice
from dbo.SalesOrderDetail_test
where ProductID = 777
go

结果集返回：
Table 'SalesOrderDetail_test'. Scan count 1, logical reads 3024, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

这次Logical Reads不变，还是3 024页，但是physical reads 和read-ahead reads都是0了。说明数据已经缓存在内存里，第二次运行不需要再从磁盘上读一遍，节省了时间。

为了不影响其他测试，请运行下面的语句关闭Set statistics io on。
Set statistics io off
Go

  3、Set statistics profile on

        这是三个设置中返回最复杂的一个，它返回语句的执行计划，以及语句运行在每一步的实际返回行数统计。

        通过这个结果，不仅可以得到执行计划、理解语句执行的过程、分析语句调优的方向，也可以判断SQL

        Server是否选择了一个正确的执行计划，如果不正确，原因又大概是什么。

本章前面已经使用过了这个设置的返回结果来分析执行计划。现在再来完整地介绍一下，先从一个最简单的查询谈起。
Set statistics profile on
go
select distinct ProductID, UnitPrice
from dbo.SalesOrderDetail_test
where ProductID = 777
go

返回的结果集很长，笔者先把它们都贴出来，比较重要的字段打上了方框记号，后面加以解释（见图17-44）。

 

Rows：执行计划的每一步返回的实际行数。

Executes：执行计划的每一步被运行了多少次。

StmtText：执行计划的具体内容。执行计划以一棵树的形式显示。每一行，都是运行的一步，都会有结果集返回，也都会有自己的cost。

EstimateRows：SQL Server根据表格上的统计信息，预估的每一步的返回行数。在分析执行计划时，我们会经常将Rows和EstimateRows这两列做对比，先确认SQL Server预估得是否准确。
EstimateIO：SQL Server根据EstimateRows和统计信息里记录的字段长度，预估的每一步会产生的I/O cost。

EstimateCPU：SQL Server根据EstimateRows和统计信息里记录的字段长度，以及要做的事情的复杂度，预估的每一步会产生的CPU cost。

TotalSubtreeCost：SQL Server根据EstimateIO和EstimateCPU通过某种计算公式，计算出的每一步执行计划子树cost（包括这一步自己的cost和它的所有下层步骤的cost总和）。

Warnings：SQL Server在运行每一步时遇到的警告，例如，某一步没有统计信息支持cost预估等。

Parallel：执行计划的这一步是不是使用了并行的执行计划。

所以上面这个简单的执行计划意思是：

（1）执行计划分成两步。

步骤a（行3）

使用Clustered Index Scan（全表扫描）的方式找出所有ProductID = 777的记录。

       |--Clustered Index Scan(OBJECT:([AdventureWorks].[dbo].[SalesOrderDetail_test]. [SalesOrderDetail_test_CL]), WHERE:([AdventureWorks].[dbo].[SalesOrderDetail_test]. [ProductID]=(777)))

这一步SQL Server预测会返回522.8行，实际返回484行，所以这一步预估得还算准确。预估cost是2.502。

步骤b（行2）

使用Sort的方式把步骤a返回的484行做一个排序，从中选出Distinct的值。

  |--Sort(DISTINCT ORDER BY:([AdventureWorks].[dbo].[SalesOrderDetail_test].[UnitPrice] ASC))

这一步SQL Server预测会返回146.1行，实际只返回了4行。所以这一步的预估有些不准确。这和SQL Server在ProductID+UnitPrice上没有直接的统计信息有关系。好在这个结果集没有用来做其他事情，直接就是查询的结果。所以预估不太准也没什么影响。

这一步的预估cost是2.637。除掉它的子步骤a的cost 2.502，这一步自己的cost是2.637 – 2.502 =0.135。

（2）执行计划是单线程运行的，也没有报出什么Warning。应该讲，是一个正常的语句。

（3）比较Rows和EstimateRows这两列，SQL Server没有少估计某一步的返回。而多估计的那一步（Step B）在多估的情况下，Cost依然比较小，自己cost只有0.135。实际的cost因为返回结果集小，应该更低。所以可以讲，整个Cost估计得还是比较准确的。主要的cost都花在了全表扫描上了（Step A）。如果要对这个语句进行调优，就要引导SQL Server不要使用Clustered Index Scan这样cost大的动作。在ProductID上加一个索引是一个比较自然的想法。

让我们再运行一句稍微复杂一点的语句，看看结果会怎么样，如图17-45所示。

 

set statistics profile on
go
select count(b.SalesOrderID)
from dbo.SalesOrderHeader_test a
inner join dbo.SalesOrderDetail_test b
on a.SalesOrderID = b.SalesOrderID
where a.SalesOrderID >43659 and a.SalesOrderID< 53660
go

从这个结果能看出来的是执行计划分成4步，其中第一步又分成并列的两个子步骤。

步骤a1（第5行）： 从SalesOrderHeader_test表里找出所有SalesOrderID >43 659 and SalesOrderID< 53 660的值。

因为表在这个字段上有一个聚集索引，所以SQL Server可以直接使用这个索引的Seek。

   |--Clustered Index Seek(OBJECT:([AdventureWorks].[dbo].[SalesOrderHeader_test]. [SalesOrderHeader_test_CL] AS [a]), SEEK:([a].[SalesOrderID] > (43659) AND [a].[SalesOrderID] < (53660)) ORDERED FORWARD)

SQL预测返回10 000条记录，实际也就返回了10 000条，这个预测是准的。这一步的cost是0.202，果然比前面的Clustered Index Scan要低很多。

步骤a2（第6行）：从SalesOrderDetail _test表里找出所有SalesOrderID >43 659 and SalesOrderID< 53 660的值。

因为表在这个字段上有一个非聚集索引，所以SQL Server可以直接使用这个索引的Seek。

   |--Index Seek(OBJECT:([AdventureWorks].[dbo].[SalesOrderDetail_test].[SalesOrderDetail_test_NCL] AS [b]), SEEK:([b].[SalesOrderID] > (43659) AND [b].[SalesOrderID] < (53660)) ORDERED FORWARD)

这里能够看出SQL Server聪明的地方。虽然查询语句只定义了SalesOrderHeader_test表上有SalesOrderID >43 659 and SalesOrderID< 53 660过滤条件，但是根据语义分析，SQL Server知道这个条件在SalesOrderDetail_test上也为真。所以SQL Server选择先把这个条件过滤，然后再做Join，这样能够大大降低Join的cost。

在这一步SQL Server预估返回50 561条记录，实际返回50 577条，Cost是0.109，也不高。

步骤b（第4行）：将a1和a2两步得到的结果集做一个Join。

   |--Hash Match(Inner Join, HASH:([a].[SalesOrderID])=([b].[SalesOrderID]))

因为SQL Server通过预估知道这两个结果集比较大，所以它直接选择了Hash Match的Join方法。SQL预估这个Join能返回50 444行，实际返回50 577行。因为SQL在两张表的SalesOrderID上都有统计信息，所以这里的预估非常准确。

这一步的cost等于TotalSubtreeCost减去它的子步骤，0.697 – 0.202 – 0.109 = 0.386，由于预估值非常准确，可以相信这里的cost就是实际每一步的cost。

步骤c（第3行）：在Join返回的结果集基础上算count(*)的值。

   |--Stream Aggregate(DEFINE:([Expr1009]=Count(*)))

这一步比较简单，count(*)的结果总是1，所以预测值是正确的。其实这一步的cost是根据上一步（b）Join返回的结果集大小预估出来的。我们知道步骤b的预估返回值非常准确，所以这一步的预估cost也不会有什么大问题。

这棵子树的cost是0.727，减去它的子结点cost，它自己的cost是0.727  0.697 = 0.03。是花费很小的一步。

步骤d（第2行）：将步骤c返回的值转换成int类型，作为结果返回。

  |--Compute Scalar(DEFINE:([Expr1006]=CONVERT_IMPLICIT(int,[Expr1009],0)))

这一步是上一步的继续，更为简单。Convert一个值的数据类型所要的cost几乎可以忽略不计，所以这棵子树的cost和它的子结点相等，都是0.727，也就是说，它自己的cost是0。

通过这样的方法，用户可以了解到语句的执行计划、SQL Server预估的准确性，以及cost的分布。下一章里，还会继续使用这些方法，来解决语句执行的性能问题。

这里顺便还要提一下执行计划里cost的值绝对大小问题。经常有人会问，两句查询的cost，是不是一句比另一句高，就一定是高的那一句比较耗时？SQL Server是跟据预测结果集（EstimateRows）大小和结果集里的数据类型推算出EstimateIO和EstimateCPU，然后再根据EstimateIO和EstimateCPU推算出TotalSubtreeCost。计算方法是所有SQL Server都一样的（只要SQL版本一样），所以在同一个SQL Server里，可以说，cost高的那一句语句一定会比较复杂。当然，前提是SQL Server要Estimate得准确。

对SQL Server来讲，它也是选择cost最低的执行计划。在“17.3.1连接（Join）”这一节例子里的那三条查询，cost最低的是使用Hash Match的连接方式，所以如果让SQL Server自己选择而不用Join Hint，它会选择Hash Match。

但是对于不同的SQL Server，由于硬件差异，SQL Server能够调动的内存、CPU、磁盘资源也会有所差异。同样Cost的语句，执行的速度会有很大的不同，所以一般不会去对比从不同SQL Server服务器上取得的执行计划里的cost。

      注：以上节选自《SQL Server 2012实施与管理实战指南》

      实战：在某软件系统中，本人发现其中的一些SQL查询语句很耗时。

        先执行

dbcc dropcleanbuffers
dbcc freeproccache

SET STATISTICS IO ON
SET STATISTICS TIME ON
select id
from local_test1.dbo.T_TASK_DETAIL
where delete_flag =0
SET STATISTICS IO OFF
SET STATISTICS TIME OFF

得到结果如下：

DBCC 执行完毕。如果 DBCC 输出了错误信息，请与系统管理员联系。
DBCC 执行完毕。如果 DBCC 输出了错误信息，请与系统管理员联系。
SQL Server 分析和编译时间:
   CPU 时间 = 0 毫秒，占用时间 = 0 毫秒。

(135712 row(s) affected)
表 'T_TASK_DETAIL'。扫描计数 1，逻辑读取 1259 次，物理读取 12 次，预读 1256 次，lob 逻辑读取 0 次，lob 物理读取 0 次，lob 预读 0 次。

 SQL Server 执行时间:
   CPU 时间 = 125 毫秒，占用时间 = 22440 毫秒。

 SQL Server 执行时间:
   CPU 时间 = 0 毫秒，占用时间 = 0 毫秒。

分析：

13万条数据，查询语句很简单，CPU耗时为125ms，有点多。根据公式 ，总耗时=CPU耗时 + 阻塞态时间 + 就绪态时间。由于从硬盘读取文件（physical reads 12，read-ahead reads1256），所以在I/O上有一定的阻塞，那它是不是耗时的主要原因呢？如果是，再次执行下面的语句，elapsed time应该显著减小。

验证：

SET STATISTICS IO ON
SET STATISTICS TIME ON
select id
from local_test1.dbo.T_TASK_DETAIL
where delete_flag =0
SET STATISTICS IO OFF
SET STATISTICS TIME OFF

结果为：

SQL Server 分析和编译时间:
   CPU 时间 = 0 毫秒，占用时间 = 0 毫秒。

(135712 row(s) affected)
表 'T_TASK_DETAIL'。扫描计数 1，逻辑读取 1259 次，物理读取 0 次，预读 0 次，lob 逻辑读取 0 次，lob 物理读取 0 次，lob 预读 0 次。

 SQL Server 执行时间:
   CPU 时间 = 78 毫秒，占用时间 = 21705 毫秒。

 SQL Server 执行时间:
   CPU 时间 = 0 毫秒，占用时间 = 0 毫秒。

对验证结果的分析：占用时间竟然没什么变化，可见，从硬盘物理读取文件导致的I/O阻塞并不是耗时的主要因素。那非运行时间就还有：从内存读取数据到CPU的时间、就绪态时间，先分析到这里吧。