Monitoring Stored Procedure Usage

I was attending a SQL Server event a few weeks back when a number of DBA types were talking about new features in SQL Server 2005. One of the topics that came up was how might you monitor execution of stored procedures. One DBA said it would be nice if he had a method to identify how many times a stored procedure (SP) was executed. He was looking for some information to help fine tune his environment and the applications running in his environment. Or at least identify the processes that where run frequently so they could be reviewed by developers to determine if they could be written more efficiently. So what new features in SQL Server 2005 might be used to accomplish the monitoring of SP executions? Dynamic Management views (DMV) of course. In this article I will show you how you can use a few DMV’s to identify the most frequently run SPs of an instance of SQL Server, as well as those SPs that use the most CPU, I/O or run the longest.

Execution Statistics
It is relatively easy to identify the use count and resource usage of your SP’s, but first let me discuss how SQL Server maintains the execution statistics. The SQL Server engine keeps execution statistics for each SQL Server 2005 instance. Execution Statistics are an accumulation of execution information about what has been run since the instances has started. Each time an instance is stopped and restarted all execution statistics are reset.

Individual execution statistics for an object are tied to cached execution plans. When a SP is compiled, an execution plan is cached in memory. These cached execution plans are uniquely identified by a plan_handle. Since memory is limited, SQL Server from time to time will remove execution plans from memory, if the cached plan is not being actively used. Therefore the statistics stored for a particular SP may be for an accumulation of stats since SQL Server started, if the SP has only be compiled once. Or, it may only have statistics for the last few minutes if the SP had recently been compiled.

How to Get the Execution Count of a Stored Procedure?
To determine how many times a stored procedure in the cache has been executed you need to use a couple of DMV’s and a dynamic management function (DMF). The plan_handle for the cached plans are used to join together the DMVs and retrieve records for a DMF. To get the execution counts for each cached SPs you can run the following code:

SELECT DB_NAME(st.dbid) DBName
,OBJECT_SCHEMA_NAME(st.objectid,dbid) SchemaName
,OBJECT_NAME(st.objectid,dbid) StoredProcedure
,sum(qs.execution_count) Execution_count
FROM sys.dm_exec_cached_plans
cp join sys.dm_exec_query_stats qs on cp.plan_handle = qs.plan_handle
CROSS APPLY sys.dm_exec_sql_text(cp.plan_handle) st
where DB_NAME(st.dbid) is not null and cp.objtype = 'proc'
group by DB_NAME(st.dbid),OBJECT_SCHEMA_NAME(objectid,st.dbid),
OBJECT_NAME(objectid,st.dbid)
order by sum(qs.execution_count) desc
Here I used the plan_handle of the “sys.dm_exec_cached_plans” DMV to join with the “sys.dm_exec_query_stats” DMV to obtain the “Execution_count” value where the object type is a store procedure. The “execution_count” column of the “sys.dm_exec_query_stats” DMV identifies the number of time the cached_plan (or SP) has been executed since the last compilation of the SP. I use the plan_handle in conjunction with the CROSS APPLY operator to return the object information (DBName, SchemaName, and ObjectName) using the table-value DMF “sys.dm_exec_sql_text”. The output from this SELECT statement is ordered by the execution_count, so the SP with the most executions will be displayed first.

Determining Which SP is using the Most CPU, I/O, or has the Longest Duration.
Knowing which SPs are frequently executed is useful information, although from a performance standpoint you might like to know which SP is consuming the greatest amount of CPU resources. Or possibly you might be interested in which SP takes the longest to run, or which SP performs the most physical I/O operations. By modifying the above command, we can easily answer each one of these questions.

If you want to show the SP that consumes the most CPU resources, you can run the following TSQL command:

SELECT DB_NAME(st.dbid) DBName
,OBJECT_SCHEMA_NAME(st.objectid,dbid) SchemaName
,OBJECT_NAME(st.objectid,dbid) StoredProcedure
,sum(qs.execution_count) Execution_count
,sum(qs.total_worker_time) total_cpu_time
,sum(qs.total_worker_time) / (sum(qs.execution_count) * 1.0) avg_cpu_time

FROM sys.dm_exec_cached_plans cp join sys.dm_exec_query_stats qs on cp.plan_handle = qs.plan_handle
CROSS APPLY sys.dm_exec_sql_text(cp.plan_handle) st
where DB_NAME(st.dbid) is not null and cp.objtype = 'proc'
group by DB_NAME(st.dbid),OBJECT_SCHEMA_NAME(objectid,st.dbid), OBJECT_NAME(objectid,st.dbid)
order by sum(qs.total_worker_time) desc

The “sys.dm_exec_query_stats” view contains the column “total_worker_time”, which is the total number of microseconds that a given cached query plan has executed. Keep in mind that cached plans are sometimes removed from memory and replaced with newer ones. Therefore, the statistics for which SP has consumed the most CPU only takes into account statistics for those plans that are in the cache when this T-SQL is run.

To determine which SP has executed the most I/O requests you can run the following TSQL code:

SELECT DB_NAME(st.dbid) DBName
,OBJECT_SCHEMA_NAME(objectid,st.dbid) SchemaName
,OBJECT_NAME(objectid,st.dbid) StoredProcedure
,sum(execution_count) execution_count
,sum(qs.total_physical_reads + qs.total_logical_reads + qs.total_logical_writes) total_IO
,sum(qs.total_physical_reads + qs.total_logical_reads + qs.total_logical_writes) / sum(execution_count) avg_total_IO
,sum(qs.total_physical_reads) total_physical_reads
,sum(qs.total_physical_reads) / (sum(execution_count) * 1.0) avg_physical_read
,sum(qs.total_logical_reads) total_logical_reads
,sum(qs.total_logical_reads) / (sum(execution_count) * 1.0) avg_logical_read
,sum(qs.total_logical_writes) total_logical_writes
,sum(qs.total_logical_writes) / (sum(execution_count) * 1.0) avg_logical_writes
FROM sys.dm_exec_query_stats qs CROSS APPLY sys.dm_exec_sql_text(qs.plan_handle) st
join sys.dm_exec_cached_plans cp on qs.plan_handle = cp.plan_handle
where DB_NAME(st.dbid) is not null and cp.objtype = 'proc'
group by DB_NAME(st.dbid),OBJECT_SCHEMA_NAME(objectid,st.dbid), OBJECT_NAME(objectid,st.dbid)
order by sum(qs.total_physical_reads + qs.total_logical_reads + qs.total_logical_writes) desc

Here I have displayed the total physical and logical read I/O’s, plus the logical write I/O’s. In addition, I have calculated the average number of I/O’s per execution of each SP. Physical reads are the number of reads that are actually made against the physical disk drives; where as logical reads and writes are the number of I/O’s against the cached data pages in memory in the buffer cache. Therefore, by adding the physical and logical I/O’s together I was able to calculate the total I/O’s for each SP.

To determine which SPs take the longest time to execute I can use the follow TSQL code:

SELECT DB_NAME(st.dbid) DBName
,OBJECT_SCHEMA_NAME(objectid,st.dbid) SchemaName
,OBJECT_NAME(objectid,st.dbid) StoredProcedure
,sum(execution_count) execution_count
,sum(qs.total_elapsed_time) total_elapsed_time
,sum(qs.total_elapsed_time) / sum(execution_count) avg_elapsed_time
FROM sys.dm_exec_query_stats qs CROSS APPLY sys.dm_exec_sql_text(qs.plan_handle) st
join sys.dm_exec_cached_plans cp on qs.plan_handle = cp.plan_handle
where DB_NAME(st.dbid) is not null and cp.objtype = 'proc'
group by DB_NAME(st.dbid),OBJECT_SCHEMA_NAME(objectid,st.dbid), OBJECT_NAME(objectid,st.dbid)
order by sum(qs.total_elapsed_time) descIn this TSQL, I am calculating the duration of each SP by summing up the “total_elapsed_time” in the “sys.dm_exec_sql_query_stats” DMV by database, schema and object name. I am also calculating the average elapsed time per execution of each SP. I order the output so the SP that took the longest total duration will be displayed first. If you where interested in determining the SP that had the longest average duration all you would need to change is the “ORDER BY” clause to sort by “avg_elapsed_time”.

ConclusionThe “sys.dm_exec_query_stats” SP is used to look at the accumulated statistics for cached plans. By joining the “sys.dm_exec_query_stats” view with other DMVs, you can determine other information about the cached plan, like the object type for the cached plan, and the actual name of the object. Having these DMVs in SQL Server 2005 now provides you with some data mining tools to review some performance information for a SQL Server instance. Next time you want to review statistics related to your code run on your SQL Server box consider looking at the information available in the SQL Server 2005 dynamic management views.