SQL Server 如何找到存储过程中最耗时的部分

       存储过程优化的重点和难点在于如何找到存储过程中最耗时的部分。尤其对于很长的存储过程，或者多层嵌套调用的存储过程，难度会更大。

大致有两种情况：

• 慢在自身SQL
• 慢在执行其他嵌套存储过程/函数/link的SQL

       

排查思路大致如下：

一、 查存储过程中各部分sql执行时间

首先从dm_exec_query_stats视图看存储过程整体的执行情况，关注最近、最小和最大执行时间，从这里可以看到存储过程执行时间是不是差异很大。

然后通过关联视图再看每部分sql执行时间，注意这里只包含本存储过程中的SQL，如果有嵌套的存储过程，其中SQL不会显示。

-- 带入存储过程的名字
select  * from 
 sys.dm_exec_procedure_stats deps,
 sys.sysobjects so
 where deps.object_id=so.id
 and NAME='myproc'

--带入 sql_handle
 SELECT getdate() as check_time,
 	(SELECT TOP 1 SUBSTRING(st.text,statement_start_offset / 2+1 ,   
      ( (CASE WHEN statement_end_offset = -1   
         THEN (LEN(CONVERT(nvarchar(max),st.text)) * 2)   
         ELSE statement_end_offset END)  - statement_start_offset) / 2+1))  AS sql_statement,  
       qs.sql_handle,
       qs.statement_start_offset,
       qs.statement_end_offset,
       qs.plan_handle,
       qs.creation_time,
       qs.execution_count,
       qs.query_hash,
       qs.query_plan_hash,
       st.text,
       qp.query_plan,
       qs.total_elapsed_time,
       qs.total_logical_reads,
       qs.total_physical_reads,
       qs.total_rows,
       qs.total_elapsed_time / qs.execution_count as elasp_per_exec,
       qs.total_logical_reads / qs.execution_count as logiread_per_exec,
       qs.total_physical_reads / qs.execution_count as phyread_per_exec,
       qs.total_rows / qs.execution_count as rows_per_exec -- into perf_tab_tsnbindinfo --插入到某个表 
  FROM sys.dm_exec_query_stats AS qs
 CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS st
 CROSS APPLY sys.dm_exec_text_query_plan(qs.plan_handle, qs.statement_start_offset, qs.statement_end_offset) AS qp
 WHERE  qs.sql_handle=0x03000700CEB3BB0C2C620201CFA9000001000000000000000000000000000000000000000000000000000000
order by elasp_per_exec desc

这里也要注意各部分SQL平均时间的总和与存储过程执行时间的差异

• 如果存储过程执行20秒，各部分SQL平均时间之和也接近20秒，说明就慢在自身的语句，可以直接分析慢SQL
• 如果存储过程执行20秒，各部分SQL平均时间之和不到50毫秒，则可能有以下情况：

1. 并不是这个存储过程里面的语句慢，而是它中途跳出去执行了别的慢存储过程/函数、或者通过link访问其他库执行慢SQL，它其实是个受害者。
2. 这个存储过程的语句大部分情况都执行很快，但如果遇到特殊的变量等，某些SQL执行时间可能变得很长。但由于这种情况比较少，各SQL的平均执行时间看起来都很短。

二、 查看存储过程实际执行计划

3. sql profile抓存储过程相关sql

设置事件：

• RPC:Completed
• SP:StmtCompleted
• SQL:BatchCompleted

开的过程就省略了，看到基本都在2秒以上（正常应在ms级别），用sql profile中抓到的语句去对比前一步正在执行的sql，发现还是没有相同的。另外这个存储过程有数据更新，也不能手动跑来看问题出在哪。

• 极限情况下可以将duration设为0，抓取存储过程所有sql执行情况，然后分析trace文件

-- 找到执行过慢的存储过程，例如6秒以上；记录 spid,starttime,endtime
select * from trace_table where duration>=6000000

-- 查询存储过程各部分sql执行次数及时间
select convert(varchar(8000),textdata),count(1) executions,sum(duration)/1000 duration_ms from trace_table a 
where spid=88 and starttime>='2021-09-16 17:11:14' and endtime<='2021-09-16 17:11:20.667' and duration<6000000
group by convert(varchar(8000),textdata)
order by 3 desc

4. 查找真正变慢的存储过程

可以看下myproc这个存储过程的内容，如果很简单、嵌套的存储过程少，可以直接搜exec依次排查。

另外由于该存储过程执行基本是2s，可以在sql profile抓1~2s内的慢sql，如果有跟这个存储过程开始、结束以及消耗时间都相近的存储过程，去查这个存储过程是否有被myproc调用，如果有，很可能这就是真正有问题的存储过程。

这次排查其实遇到一个挺特殊的情况，从sql profile中看到spid不是599就是776，来来回回都是这两个，想到去查这两个spid到底在执行什么语句。

执行第1步的sql发现两个spid都在执行一个insert 临时表 select 的语句，该语句对应的存储过程有被myproc调用，并且执行时间经常在1s以上，很有可能就是这个insert语句导致的。

5. 优化真正的慢sql

进一步检查发现其中的select语句走错了索引，没有走到好的执行计划，尝试清除其当前执行计划，让它重新生成。

DBCC FREEPROCCACHE(0x060001002903DC0B4001B887000000000000000000000000);
-- 0x060001002903DC0B4001B887000000000000000000000000为insert语句的plan_handle

清除完之后再看sql profile发现myproc存储过程执行回到了ms级，业务恢复，确实是由于该insert执行计划改变导致了这次问题。

关于走错的那个索引，索引字段值偏差非常大，最多的值有超过900万个而最少的只有8个。可能某一次sql解析的时候，由于刚好代入了非常少的值，走该索引比之前正确的索引更高效，就缓存了起来。但对绝大多数值来说，走该索引都是低效的，导致后面语句统统变慢，这是典型的sqlserver参数嗅探问题。

6. 后续改进

一般并不建议在偏差值如此大的字段上建索引，如果能确定该索引没用的话可以直接删除。当然通常这都很难确定，谁知道啥时候又要用了。

后续如果不想再出现该问题，一是给sql绑定执行计划，二是给该sql加hint指定索引。对该语句来说，加hint比较方便，开发选择紧急发版，添加hint。

参考

http://www.ithov.com/server/124121.shtml

清除SQL Server数据缓存和执行计划缓存,查看执行计划的各种方式对比 _princelintb的专栏-CSDN博客