Finding Poorly Performing Stored Procedures

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] bigint,
 [Avg. CPU Time(s)] DECIMAL(28,2),
 [Avg. Physical Reads] bigint,
 [Avg. Logical Reads] bigint,
 [Avg. Logical Writes] bigint,
 [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] bigint,
 [Last Physical Reads] bigint,
 [Min Physical Reads] bigint,
 [Max Physical Reads] bigint,
 [Total Logical Reads] bigint,
 [Last Logical Reads] bigint,
 [Min Logical Reads] bigint,
 [Max Logical Reads] bigint,
 [Total Logical Writes] bigint,
 [Last Logical Writes] bigint,
 [Min Logical Writes] bigint,
 [Max Logical Writes] bigint,
 [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

Advertisements

3 thoughts on “Finding Poorly Performing Stored Procedures

  1. Simon,

    Indeed a very useful blog for performance turning. Thanks for the post.

    When I am executing this query on SQL Server 2008 Enterprises instance, I am getting the following error. Can you please guide.

    Msg 8115, Level 16, State 2, Line 49
    Arithmetic overflow error converting expression to data type int.
    The statement has been terminated.

  2. Hi,

    I’m glad you like the post! In the initial table creation I’ve declared many of the data types as INT. It is most likely that some of the nos. that your server is returning are larger than an INT can hold. Change the column datatype in the temp table to BIGINT and that should sort it. I’ll update the query myself now too.

    Thanks,

    Simon

  3. Hello Simon, It took some time to me to use this again. with BIGINT, it’s working fine. Thanks again for such a wonderful handy script. No doubt that such these handy tools make DBA’s life easier.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s