The Coeo Blog

Finding Poorly Performing Stored Procedures

Written by Simon Osborne | 08-Jul-2013 11:03:54

Hi,

Following on from my script that looks at poorly performing queries, here’s one that helps to find procedures that may be performing poorly. It makes use of sys.dm_exec_procedure_stats and produces a result set that shows the following:

  • [Object]
  • [SQLText]
  • [QueryPlan]
  • [execution_count]
  • [Avg. CPU Time(s)]
  • [Avg. Physical Reads]
  • [Avg. Logical Reads]
  • [Avg. Logical Writes]
  • [Avg. Elapsed Time(s)]
  • [Total CPU Time(s)]
  • [Last CPU Time(s)]
  • [Min CPU Time(s)]
  • [Max CPU Time(s)]
  • [Total Physical Reads]
  • [Last Physical Reads]
  • [Min Physical Reads]
  • [Max Physical Reads]
  • [Total Logical Reads]
  • [Last Logical Reads]
  • [Min Logical Reads]
  • [Max Logical Reads],
  • [Total Logical Writes]
  • [Last Logical Writes]
  • [Min Logical Writes]
  • [Max Logical Writes]
  • [Total Elapsed Time(s)]
  • [Last Elapsed Time(s)]
  • [Min Elapsed Time(s)]
  • [Max Elapsed Time(s)]
  • cached_time
  • last_execution_time

I hope you find it useful.

SET NOCOUNT ON;

/*****************************************************
Setup a temporary table to fetch the data we need from
sys.dm_exec_procedure_stats.
******************************************************/
IF OBJECT_ID('tempdb..#temp') IS NOT NULL DROP TABLE #temp
CREATE TABLE #temp
(
database_id INT,
object_id INT,
[SQLText] VARCHAR(MAX),
[QueryPlan] XML,
[execution_count] int,
[Avg. CPU Time(s)] DECIMAL(28,2),
[Avg. Physical Reads] INT,
[Avg. Logical Reads] INT,
[Avg. Logical Writes] INT,
[Avg. Elapsed Time(s)] DECIMAL(28,2),
[Total CPU Time(s)] DECIMAL(28,2),
[Last CPU Time(s)] DECIMAL(28,2),
[Min CPU Time(s)] DECIMAL(28,2),
[Max CPU Time(s)] DECIMAL(28,2),
[Total Physical Reads] INT,
[Last Physical Reads] INT,
[Min Physical Reads] INT,
[Max Physical Reads] INT,
[Total Logical Reads] INT,
[Last Logical Reads] INT,
[Min Logical Reads] INT,
[Max Logical Reads] INT,
[Total Logical Writes] INT,
[Last Logical Writes] INT,
[Min Logical Writes] INT,
[Max Logical Writes] INT,
[Total Elapsed Time(s)] DECIMAL(28,2),
[Last Elapsed Time(s)] DECIMAL(28,2),
[Min Elapsed Time(s)] DECIMAL(28,2),
[Max Elapsed Time(s)] DECIMAL(28,2),
cached_time DATETIME,
last_execution_time DATETIME,
[object] VARCHAR(MAX) NULL
)

/*****************************************************
Fetch the data we need from
sys.dm_exec_procedure_stats.
******************************************************/
insert into #temp
select
database_id,
object_id,
st.text,
ep.query_plan,
execution_count,

-- Averages
CAST(total_worker_time * 1.0 / execution_count / 1000000.0 as DECIMAL(28,2)) AS [Avg. CPU Time(s)],
total_physical_reads / execution_count AS [Avg Physical Reads],
total_logical_reads / execution_count AS [Avg. Logical Reads],
total_logical_writes / execution_count AS [Avg. Logical Writes],
CAST(total_elapsed_time * 1.0 / execution_count / 1000000.0 as DECIMAL(28,2)) AS [Avg. Elapsed Time(s)],

-- CPU Details
CAST(total_worker_time / 1000000.0 as DECIMAL(28,2)) AS [Total CPU Time(s)],
CAST(last_worker_time / 1000000.0 as DECIMAL(28,2)) AS [Last CPU Time(s)],
CAST(min_worker_time / 1000000.0 as DECIMAL(28,2)) AS [Min CPU Time(s)],
CAST(max_worker_time / 1000000.0 as DECIMAL(28,2)) AS [Max CPU Time(s)],

-- Physical Reads
total_physical_reads AS [Total Physical Reads],
last_physical_reads AS [Last Physical Reads],
min_physical_reads AS [Min Physical Reads],
max_physical_reads AS [Max Physical Reads],

-- Logical Reads
total_logical_reads AS [Total Logical Reads],
last_logical_reads AS [Last Logical Reads],
min_logical_reads AS [Min Logical Reads],
max_logical_reads AS [Max Logical Reads],

-- Logical Writes
total_logical_writes AS [Total Logical Writes],
last_logical_writes AS [Last Logical Writes],
min_logical_writes AS [Min Logical Writes],
max_logical_writes AS [Max Logical Writes],

-- Elapsed Time
CAST(total_elapsed_time / 1000000.0 as DECIMAL(28,2)) AS [Total Elapsed Time(s)],
CAST(last_elapsed_time / 1000000.0 as DECIMAL(28,2)) AS [Last Elapsed Time(s)],
CAST(min_elapsed_time / 1000000.0 as DECIMAL(28,2)) AS [Min Elapsed Time(s)],
CAST(max_elapsed_time / 1000000.0 as DECIMAL(28,2)) AS [Max Elapsed Time(s)],

cached_time,
last_execution_time,
null
from
sys.dm_exec_procedure_stats
CROSS APPLY sys.dm_exec_sql_text(sql_handle) st
CROSS APPLY sys.dm_exec_query_plan(plan_handle) ep
where
database_id <> 32767

/*****************************************************
This section of code is all about getting the object
name from the dbid and the object id.
******************************************************/

-- Declare a Cursor
DECLARE FetchObjectName CURSOR FOR
SELECT
object_id, database_id
FROM
#temp

-- Open the cursor
OPEN FetchObjectName

-- Declare some vars to hold the data to pass into the cursor
DECLARE @var1 INT,
@var2 INT
DECLARE @sql VARCHAR(MAX)
DECLARE @object VARCHAR(MAX)

-- Create a temporary table to hold the result of the dynamic SQL
IF OBJECT_ID('tempdb..#object') IS NOT NULL DROP TABLE #object
CREATE TABLE #object
(
objectname VARCHAR(MAX)
)

-- Loop through the 20 records from above and fetch the object names
FETCH NEXT FROM FetchObjectName INTO @var1, @var2
WHILE ( @@FETCH_STATUS <> -1 )
BEGIN
IF ( @@FETCH_STATUS <> -2 )

-- Set the SQL we need to execute
SET @sql = 'USE [' + DB_NAME(@var2) + '];
SELECT OBJECT_SCHEMA_NAME(' + CONVERT(VARCHAR(MAX),@var1) + ',' + CONVERT(VARCHAR(MAX),@var2) + ') + ''.'' + ' + 'OBJECT_NAME(' + CONVERT(VARCHAR(MAX),@var1) + ');'

-- Make sure the table is empty!
TRUNCATE TABLE #object

-- Fetch the name of the object
INSERT INTO #object
EXEC(@sql)

-- Set the object name to the local var.
SELECT @object = objectname FROM #object

-- Update the original results
UPDATE #temp
SET
[Object] = RTRIM(LTRIM(@object))
WHERE
object_id = @var1
and database_id = @var2

-- Go around the loop....
FETCH NEXT FROM FetchObjectName INTO @var1, @var2
END
CLOSE FetchObjectName
DEALLOCATE FetchObjectName
/*****************************************************
Output the final restults....
******************************************************/
SELECT TOP 50
db_name(database_id) + '.' + [Object] AS [Object],
[SQLText],
[QueryPlan],
[execution_count],
[Avg. CPU Time(s)],
[Avg. Physical Reads],
[Avg. Logical Reads],
[Avg. Logical Writes],
[Avg. Elapsed Time(s)],
[Total CPU Time(s)],
[Last CPU Time(s)],
[Min CPU Time(s)],
[Max CPU Time(s)],
[Total Physical Reads],
[Last Physical Reads],
[Min Physical Reads],
[Max Physical Reads],
[Total Logical Reads],
[Last Logical Reads],
[Min Logical Reads],
[Max Logical Reads],
[Total Logical Writes],
[Last Logical Writes],
[Min Logical Writes],
[Max Logical Writes],
[Total Elapsed Time(s)],
[Last Elapsed Time(s)],
[Min Elapsed Time(s)],
[Max Elapsed Time(s)],
cached_time,
last_execution_time
FROM
#temp
ORDER BY
[Avg. Logical Reads] DESC