MSSQL如何获取存储过程中正在执行的真实SQL语句(定位存储过程中最耗时部分)
Tags： MSSQLSQL ServerSQL语句存储过程慢SQL正在执行
👉 本文共约1261个字，系统预计阅读时间或需5分钟。
存储过程优化的重点和难点在于如何找到存储过程中最耗时的部分。尤其对于很长的存储过程，或者多层嵌套调用的存储过程，难度会更大。
大致有两种情况：
- 慢在自身SQL
- 慢在执行其他嵌套存储过程/函数/link的SQL
需求
SQL server如何找到存储过程中的正在执行的真实的sql语句?????
模拟存储过程一直在运行：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 | drop PROCEDURE LongRunningProcedure; go CREATE PROCEDURE LongRunningProcedure AS BEGIN SET NOCOUNT ON; DECLARE @Counter INT = 0; WHILE @Counter < 1000000 BEGIN -- Perform complex queries and logic here WAITFOR DELAY '00:00:05'; -- Wait for 5 seconds WAITFOR DELAY '00:00:06'; SET @Counter = @Counter + 1; END END LongRunningProcedure |
方法1：直接查询
以下SQL的internal_SQL_TEXT就是存储过程真实的内部SQL，而Parent_SQL_TEXT就是存储过程全部内容。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 | SELECT spid, blocked blocking, P.dbid, db_name(P.dbid) dbname, (waittime/1000) waittime, lastwaittype, waitresource, open_tran, P.status, cpu, physical_io, memusage, login_time, last_batch, hostname, [program_name], hostprocess, cmd, nt_domain, nt_username, net_address, net_library, loginame, P.sql_handle, SUBSTRING (s.text, er.statement_start_offset/2, (CASE WHEN er.statement_end_offset = -1 THEN LEN(CONVERT(NVARCHAR(MAX), s.text)) * 2 ELSE er.statement_end_offset END - er.statement_start_offset)/2) internal_SQL_TEXT, TEXT Parent_SQL_TEXT, 'kill '+cast(spid as varchar) kill1 FROM master.dbo.sysprocesses P LEFT JOIN sys.dm_exec_requests er with(nolock) ON er.session_id = P.spid CROSS apply sys.dm_exec_sql_text (P.sql_handle) s WHERE P.spid <>@@spid and (P.status !='sleeping' or (P.status='sleeping' and P.spid IN(select blocked from master.dbo.sysprocesses nb with(nolock) where blocked > 0 )) or (P.status='sleeping' and P.open_tran >0 ) ) order by waittime desc GO |
方法2：SQL Server Profiler（推荐）
通过 SQL Server Management Studio，可以使用 SQL Server Profiler 来监视数据库活动。在 SQL Server Profiler 中，选择 "TSQL_SPs" 模板，建议保存到表中，然后选择spid列，然后启动跟踪会话。在跟踪结果中，可以查看每个存储过程的执行情况，以及存储过程中执行的实际 SQL 语句。
勾选显示所有事件，然后设置事件：
Stored Procedures下的
RPC:Completed
SP:StmtCompleted
TSQL下的：
本人提供Oracle(OCP、OCM)、MySQL(OCP)、PostgreSQL(PGCA、PGCE、PGCM)等数据库的培训和考证业务，私聊QQ646634621或微信db_bao，谢谢！
- SQL:BatchCompleted
极限情况下可以将duration设为0，抓取存储过程所有sql执行情况，然后分析trace文件
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 | -- 找到执行过慢的存储过程，例如6秒以上；记录 spid,starttime,endtime select * from trace_table where Duration>=6000000; select a.Duration/1000000 Duration_S,a.* from trace_table a where Duration>=6000000 ORDER BY Duration DESC ; -- 查询存储过程各部分sql执行次数及时间 select top 10 convert(varchar(8000),TextData),count(1) executions,sum(Duration)/1000000 duration_s from trace_table a -- where Duration<6000000 group by convert(varchar(8000),TextData) order by 3 desc; 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; |
方法3：查存储过程中各部分sql执行时间
首先从dm_exec_query_stats视图看存储过程整体的执行情况，关注最近、最小和最大执行时间，从这里可以看到存储过程执行时间是不是差异很大。
然后通过关联视图再看每部分sql执行时间，注意这里只包含本存储过程中的SQL，如果有嵌套的存储过程，其中SQL不会显示。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 | -- 带入存储过程的名字 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 ; SELECT TOP 10 a.OBJECT_ID as td, a.database_id as td, DB_NAME(a.database_id) as td, OBJECT_NAME(object_id, a.database_id) as td, a.type as td, a.type_desc as td, a.sql_handle as td, a.cached_time as td, a.last_execution_time as td, a.total_elapsed_time as td, a.total_elapsed_time/a.execution_count as td, a.execution_count as td, a.total_physical_reads/a.execution_count as td, a.total_logical_writes as td, a.total_logical_writes/ a.execution_count as td, a.last_elapsed_time as td, '<textarea style="width:600px;font-family:Consolas;font-size:11px;overflow:auto" rows="3">' + isnull(b.text ,' ')+'</textarea>' as td FROM sys.dm_exec_procedure_stats AS a CROSS APPLY sys.dm_exec_sql_text(a.sql_handle) b CROSS APPLY sys.dm_exec_query_plan(a.plan_handle) c WHERE a.database_id not in (32767) ORDER BY [total_worker_time] DESC; |
这里也要注意各部分SQL平均时间的总和与存储过程执行时间的差异
如果存储过程执行20秒，各部分SQL平均时间之和也接近20秒，说明就慢在自身的语句，可以直接分析慢SQL
如果存储过程执行20秒，各部分SQL平均时间之和不到50毫秒，则可能有以下情况：
并不是这个存储过程里面的语句慢，而是它中途跳出去执行了别的慢存储过程/函数、或者通过link访问其他库执行慢SQL，它其实是个受害者。
这个存储过程的语句大部分情况都执行很快，但如果遇到特殊的变量等，某些SQL执行时间可能变得很长。但由于这种情况比较少，各SQL的平均执行时间看起来都很短。
总结
1、推荐方法2
