12.0 Plan Cache Trace Events and Performance Counters

[sshekar]

First published on MSDN on Jan 19, 2007

<br/><!--<br/> p.MsoNormal<br/> {mso-style-parent:"";<br/> margin-bottom:.0001pt;<br/> font-size:12.0pt;<br/> font-family:"Times New Roman";<br/> margin-left:0in; margin-right:0in; margin-top:0in}<br/> table.MsoNormalTable<br/> {mso-style-parent:"";<br/> font-size:10.0pt;<br/> font-family:"Times New Roman";<br/> }<br/>--><br/>

12.1 Trace Events

12.1.1 Performance Statistics Trace Event

The performance statistics trace event introduced in SQL Server 2005, gives persisted plan and runtime statistics information. With the information part of the trace event data when combined with the information available through the plan cache DMV sys.dm_exec_query_stats the performance history of any query can be reconstructed. The advantage of capturing this information via trace along with other plan cache trace events is that the trace data can be persisted by saving it to a trace file on the disk. The trace file contains a chronological list of trace events fired including query plans that can be analyzed for poor plans causing performance problems.

In SQL Server 2000, monitoring applications would have to capture SQL:BatchStarting, SQL:BatchCompleted and the ShowPlanXML events typically and analyze the trace data from all these events for performance problems. The batch starting and completed events are fired every time batch is executed and can be high volume events causing some performance degradation. In SQL Server 2005, the performance statistics trace event essentially obliterates the need to monitor these three different events. The trace data from the performance statistics trace event can be analyzed for poor plans causing performance problems. Performance statistics trace event is also a relatively lower volume trace (compared to the batch started and completed events) event since it is fired for unique queries and not every query.

The performance statistics trace event has 4 subclasses:

select distinct * from sys.trace_subclass_values

where trace_event_id = 165

and trace_column_id = 21

order by trace_event_id, subclass_value

go

Trace_event_id	Trace_column_id	Subclass_name	Subclass_value
165	21	SQL	0
165	21	SP:Plan	1
165	21	Batch:Plan	2
165	21	QueryStats	3

Sql batch text event (Subclass_name: SQL) is fired when sql text is inserted into the SQLMGR cache. This event subclass has batch scope; it fired once for every batch. The sql batch text event is not fired for object plans.

The object plan (Subclass_name: SP:Plan) and adhoc plan (Subclass_name: Batch:Plan) events are scoped at the statement level and are fired whenever the query is compiled or recompiled. They are not fired for queries with recompile hints. The adhoc plan events are fired only for DML and select queries and not for DDL, declare statements, while loop statements etc.

The run time stats event (Subclass_name: QueryStats) is fired when a compiled plan is removed from cache due to reasons including recompilation or memory pressure. The TextData column here contains the query execution statistics.

BOL has information regarding the trace event columns and how to interpret the trace data in the various columns for each even subclass.

Let us look at an example to see how to use performance statistics trace event:

Create a file trace with the performance statistics trace event (event id = 165) on the server:

Now suppose we have table that contains the all sales information and has three columns: transaction id, country id, and total_amount. The transaction id is the primary key column. In addition, the table has a non clustered index on the country id column. We also know that majority of the sales occur in country with id = 1, and country with id = 2 has far fewer rows in the sales table. If we had a stored procedure that reported sales by country id as below:

create proc sales_report @country_id int

as begin

select * from sales where country_id = @country_id

end

go

Now let us suppose this procedure is executed with parameter value 2 to generate the sales report for country id 2:

exec sales_report 2

go

The parameter value is sniffed in this case and we do an index seek (more details availbel in this previous posting).

Now consider the scenario where the system after achieving certain predictable performance for a period of time, now shows a sudden deterioration(an unexpected) in performance when the same stored procedure is re-executed with same parameter value (country id 2). Analyzing the performance statistics trace data in conjunction with the query statistics reported in sys.dm_exec_query_stats give important clues in understanding the reason for this unexpected drop in performance. Now let us check the DMVs to find get the query plan and the execution time statistics:

select total_worker_time/execution_count as avg_cpu_time,

substring(st.text, (qs.statement_start_offset/2) + 1,

((case statement_end_offset

when -1

then datalength(st.text)

else

qs.statement_end_offset

end

- qs.statement_start_offset)/2) + 1) as statement_text

, cast(query_plan as xml)

from sys.dm_exec_query_stats qs

cross apply sys.dm_exec_sql_text(qs.sql_handle) st

cross apply sys.dm_exec_text_query_plan(qs.plan_handle, qs.statement_start_offset, qs.statement_end_offset)

order by total_worker_time/execution_count desc;

go

Avg_ Cpu_ Time	Statement_ Text	Query_plan
126408	select * from sales where country_id = @country_id	<ShowPlanXML . . PhysicalOp= "Clustered Index Scan" LogicalOp= "Clustered Index Scan" . <ParameterList> <ColumnReference Column="@country_id" ParameterCompiledValue="(1)" /> . </ShowPlanXML>

From the query plan we can see that we are now doing an index scan and the sniffed parameter value is 1. This means the plan that was cached after the initial execution of the stored procedure with parameter value country id = 2 was probably removed from cache. Further, it a new plan for the stored procedure was inserted into cache, this time with parameter value country id = 2.

The performance statistics trace event data can confirm if indeed this was what happened. The stored procedure below analyzes the performance statistics trace data looking for object plans that are first inserted into cache and later deleted by matching the sql and plan handles. From the run time stats event, the average CPU time of the deleted plan is computed. The deleted query plan is obtained from the TextData column of the object plan event. The average CPU time of the new cached plan is computed from sys.dm_exec_query_stats. The query plan is available in sys.dm_exec_text_query_plan.

create procedure analyze_perf_stats_trace_data

as

begin

if object_id('trace_data', 'U') is not null

drop table trace_data;

if object_id('perf_stats_data_inserted', 'U') is not null

drop table perf_stats_data_inserted;

if object_id('perf_stats_data_deleted', 'U') is not null

drop table perf_stats_data_deleted;

if object_id('perf_stats_inserted_with_corresponding_deleted_object_events', 'U') is not null

drop table perf_stats_inserted_with_corresponding_deleted_object_events;

if object_id('perf_stats_deleted_with_corresponding_inserted_object_events', 'U') is not null

drop table perf_stats_deleted_with_corresponding_inserted_object_events;

if object_id('perf_stats_removed_plan', 'U') is not null

drop table perf_stats_removed_plan;

create table perf_stats_inserted_with_corresponding_deleted_object_events (TextData xml, EventClass int,

EventSubClass int, SqlHandle varbinary(64),

PlanHandle varbinary(64), StartTime datetime,

EventSequence int, PlanGenerationNumber bigint,

IntegerData2 int, Offset int);

create table perf_stats_deleted_with_corresponding_inserted_object_events (TextData xml, EventClass int,

EventSubClass int, SqlHandle varbinary(64),

PlanHandle varbinary(64), StartTime datetime,

EventSequence int, PlanGenerationNumber bigint,

IntegerData2 int, Offset int);

---read all the trace data from file

select * into trace_data from

::fn_trace_gettable ('c:\temp\perfstats.trc', default);

---select all rows corresponding to all object events

---cast the Sql and Plan Handle into varbinary(64)

select convert(xml, TextData) as TextData, EventClass,

EventSubClass,  convert(varbinary(64), SqlHandle) as SqlHandle,

convert(varbinary(64), PlanHandle) as PlanHandle,

StartTime, EventSequence, BigintData1,

IntegerData2, Offset

into perf_stats_data_inserted

from trace_data

where EventClass = 165 and

EventSubClass = 1;

---select all rows corresponding to query stats events

---these events are generated when an plan is removed from cache

---for object and adhoc plans

select convert(xml, TextData) as TextData, EventClass,

EventSubClass, convert(varbinary(64), SqlHandle) as SqlHandle,

convert(varbinary(64), PlanHandle) as PlanHandle,

StartTime, EventSequence, BigintData1,

IntegerData2, Offset

into perf_stats_data_deleted

from trace_data

where EventClass = 165 and

EventSubClass = 3;

/* for every query statistics (plan deleted event) find the corresponding plan inserted events (object plans only). The plan inserted event should have lower event sequence number tha the QE stats event so we find plan insert events that occured earlier than the QE stats events. It should also have the

same plan handle as the QE stats event, statement start and end offset as the QE stats event. The QE stats and object plan events should also have the same plan generation number (bigintdata1). By matching plan generation numbers

we avoid duplicate rows from recompiles.

*/

declare @TextData xml, @EventClass int, @EventSubClass int, @SqlHandle varbinary(64), @PlanHandle varbinary(64), @StartTime datetime, @EventSequence int, @PlanGenerationNum bigint,

@IntegerData2 int, @Offset int;

declare event_cursor cursor for select * from perf_stats_data_deleted;

open event_cursor;

fetch next from event_cursor into @TextData, @EventClass, @EventSubClass, @SqlHandle, @PlanHandle, @StartTime, @EventSequence, @PlanGenerationNum, @IntegerData2, @Offset;

while @@fetch_status =0

begin

insert into perf_stats_inserted_with_corresponding_deleted_object_events

select * from perf_stats_data_inserted where EventSequence < @EventSequence

and PlanHandle = @PlanHandle and BigIntData1 = @PlanGenerationNum

and IntegerData2 = @IntegerData2 and Offset = @Offset;

if exists(select * from perf_stats_data_inserted where EventSequence < @EventSequence

and PlanHandle = @PlanHandle)

insert into perf_stats_deleted_with_corresponding_inserted_object_events values(@TextData, @EventClass, @EventSubClass, @SqlHandle,

@PlanHandle, @StartTime, @EventSequence, @PlanGenerationNum, @IntegerData2, @Offset)

fetch next from event_cursor into @TextData, @EventClass, @EventSubClass, @SqlHandle,

@PlanHandle, @StartTime, @EventSequence, @PlanGenerationNum, @IntegerData2, @Offset;

end

close event_cursor;

deallocate event_cursor;

---compute the CPU time of the deleted plan from the QE stats

---event Text Data, plan handle, sql handle, and query plan that ---was removed and save the data into a table

select

d.TextData.value('(/QueryExecutionStats/WorkerTime/@Total)[1]', 'bigint') /

d.TextData.value('(/QueryExecutionStats/GeneralStats/@ExecutionCount)[1]', 'bigint')

as avg_cpu_time_removed,

i.TextData as query_plan_removed,

d.PlanGenerationNumber as plangenerationnum_removed,

d.PlanHandle as planhandle_removed,

d.SqlHandle as sqlhandle

into perf_stats_removed_plan

from

perf_stats_deleted_with_corresponding_inserted_object_events d, perf_stats_inserted_with_corresponding_deleted_object_events i

where i.PlanHandle = d.PlanHandle;

---note that plan generation numbers >2 indicate recompiles

select * from perf_stats_removed_plan;

/* Check if sys.dm_exec_query_stats has any rows with same Sql Handle and plan generation one greater than the deleted plan

If yes, get the CPU time, sql text, query plan, plan handle, sql handle compare results from this query with rows from perf_stats_removed_plan to indentify queries that are running slower */

declare @Sql_Handle varbinary(64), @PlanGenNum bigint;

declare event_cursor cursor for

select distinct sqlhandle, plangenerationnum_removed from perf_stats_removed_plan;

open event_cursor;

fetch next from event_cursor into @Sql_Handle, @PlanGenNum;

while @@fetch_status =0

begin

if exists(select * from sys.dm_exec_query_stats where sql_handle = @Sql_Handle and plan_generation_num <= @PlanGenNum + 1)

select total_worker_time/execution_count as avg_cpu_time_current,

substring(st.text, (qs.statement_start_offset/2) + 1,

((case statement_end_offset

when -1

then datalength(st.text)

else

qs.statement_end_offset

end

- qs.statement_start_offset)/2) + 1) as statement_text,

cast(query_plan as xml) as query_plan_current,

plan_generation_num as plan_generation_num_current,

plan_handle as planhandle_current,

sql_handle as sqlhandle

from sys.dm_exec_query_stats qs

cross apply sys.dm_exec_sql_text(qs.sql_handle) st

cross apply sys.dm_exec_text_query_plan(qs.plan_handle, qs.statement_start_offset, qs.statement_end_offset)

where qs.sql_handle = @Sql_Handle and

qs.plan_generation_num <= @PlanGenNum + 1 ;

fetch next from event_cursor into @Sql_Handle, @PlanGenNum;

end

close event_cursor;

deallocate event_cursor;

end

go

exec analyze_perf_stats_trace_data

go

The results returned by the stored procedure as below.

Avg_ cpu_ time_ Removed	Query_ Plan_ Removed	Plan gene ration num_ removed	Plan handle_ removed	Sql Handle
229	<ShowPlanXML . . PhysicalOp="Index Seek" LogicalOp="Index Seek" . . Column="@country_id" ParameterCompiledValue="(2)" /> . . </ShowPlanXML>	1	0x050001 00894682 0FB8010C 05000000 00000000 00000000 00	0x030001 00894682 0F639506 01B89800 00010000 00000000 00

Avg_ cpu_ time_ current	Statement_ text	Query_ Plan_ current	Plan gene ration num_ current	Plan handle_ current	Sql Handle
126408	select * from sales where country_id = @country_id	<ShowPlanXML . . PhysicalOp= "Clustered Index Scan" LogicalOp= "Clustered Index Scan" . . Column= "@country_id" Parameter CompiledValue ="(1)" /> . . </ShowPlanXML>	1	0x050001 00894682 0FB8C118 05000000 00000000 00000000 00	0x030001 00894682 0F639506 01B89800 00010000 00000000 00

From the result set returned by the above stored procedure we can explain the slow down in execution time due to a new query plan. The plan handles are different while the sql handles are the same indicating we have a different plan for the exact same batch text. The plans before and after have a plan generation number of 1 indicating no recompiles occurred.

In the old query plan the parameter value was sniffed and we did an index seek to get all rows with country id 2. After the plan is deleted from cache (due to memory pressure or cache flush), the stored procedure is now executed with parameter value (country id = 1). The query plan does an index scan for sniffed parameter value 1. Now, when the stored procedure is executed with country id 2, we get poor performance because we re-use the cached plan which is not the optimal plan for country id 2.

Now let us look an example with recompiles:

create table t1 (a int, b int)

go

insert into t1 values (1, 1)

go

create procedure RowCountDemo

as

begin

declare @i int;

set @i = 0;

while (@i < 1000)

begin

insert into t1 values (@i, 2*@i - 50);

select a from t1 where a < 10 or ((b > 20 or a >=100) and (a < 10000)) group by a ;

set @i = @i + 1;

end

end

go

exec RowCountDemo

go

As described in this whitepaper , after 500 modifications to a table, any stored procedure referencing that table will need to be recompiled because the table statistics needs to be refreshed.

Now execute procedure analyze_perf_stats_trace_data and examine the result sets generated:

Avg_ cpu_ time_ Remo ved	Query_ Plan_ Removed	Plan gen era tion num_ remo ved	Plan handle_ removed	Sql Handle
3558	<ShowPlanXML . . <RelOp NodeId="0" PhysicalOp ="Sort" LogicalOp ="Distinct Sort" . . </ShowPlanXML>	1	0x050001 0047E572 35B82199 04000000 00000000 00000000 00	0x030001 0047E572 35DD9000 01BA9800 00010000 00000000 00

Avg_ cpu_ time_ current	Statement_ text	Query_ Plan_ current	Plan gene ration num_ current	Plan handle_ current	Sql Handle
53	insert into #t1 values (@i, 2*@i - 50);	<ShowPlanXML . . <RelOp NodeId="0" PhysicalOp= "Table Insert" LogicalOp ="Insert" . . </ShowPlanXML>	1	0x050001 0047E572 35B82199 04000000 00000000 00000000 00	0x030001 0047E572 35DD9000 01BA9800 00010000 00000000 00
1166	select a from #t1 where a < 10 or ((b > 20 or a >=100) and (a < 10000)) group by a ;	<ShowPlanXML . . <RelOp NodeId="1" PhysicalOp ="Table Scan" LogicalOp ="Table Scan" . . </ShowPlanXML>	2	0x050001 0047E572 35B82199 04000000 00000000 00000000 00	0x030001 0047E572 35DD9000 01BA9800 00010000 00000000 00

There are several things to note here:

1.       Now the removed plan (from the query stats event) has a plan generation number of 1, while the current plan has a plan generation number of 2, and this indicates a recompile of the select query occurred.  Also notice that both the sql and plan handles are the same because the query was recompiled.

2.       A stored procedure can have several queries. For each one of these queries an object plan event is fired. To find the exact query that caused the recompile and therefore the query stats event to be fired, we would need to search for:

a.       Object plan events that occurred earlier than the query stats event (i.e. object plan events with a lower EventSequence than the query stats events.

b.       Object plan events that have the same plan handle as the query stats event.

c.       Object plan events that have the same statement offsets (trace columns IntegerData2 and Offset) as the query stats event.

This would identify the object plan event corresponding to the query stats event.

12.1.2 Cache Hit, Miss, Insert and Remove Events

The SP:Cache Hit, Miss, Insert and Remove events are fired for compiled plans only. None of these events are part of the default trace. In this section we will describe briefly when these trace events are fired and changes made to plan cache trace events in SQL Server 2005.

It was observed that 99% of cases when a SP:Cache Miss event was fired, it was followed immediately by a SP:Cache Insert event with the exact same information. In the interest of keeping trace event volume low and eliminating duplicate trace information, in SQL Server 2005 we fire the SP:Cache Miss event only if the cache miss is not immediately followed by an cache insert. In other words, we defer the decision to fire the SP:Cache Miss event until we determine if we will fire an SP:Cache Insert event.

Consider a case when the compiled plan for the query below is not found in cache, and new compiled plan is inserted into cache:

select * from t1 where col1 = 5

go

TextData	Event Class	Data base Id	Data base Name	Object Id	Object Type	SPID
(@1 tinyint)SELECT * FROM [t1] WHERE [col1]=@1	SP:Cache Insert	1	master	2573 0849	20816 - PQ	58
select * from t1 where col1 = 5	SP:Cache Insert	1	master	9039 31361	20801 - AQ	58

When this query is executed for the first time, since a compiled plan for the query is not found in cache, the query is compiled and both the parameterized and the shell query are inserted into cache. In this case we fire the SP:Cache Insert event two times: once for the parameterized query and once for the shell query. Notice that we don’t fire the SP:Cache Miss event at all in this case. The firing of the SP:Cache Miss event is deferred until we determine whether or not to fire an SP:Cache Insert event. If we do fire the cache insert event, we will not fire the cache miss event. This optimization significantly reduces event volume without compromising on information we provide to the user via trace events. Another interesting thing to note here is that for prepared and adhoc compiled plans, the objectid column does not contain the ID of the object in the query as reported in sys.objects. It is a hash of the sql text. The DatabaseId column gives the id of the database from which the query was executed.

We adopt a similar strategy for stored procedures/functions as well as demonstrated in the example below:

exec sales_report @country_id = 2

go

TextData	Event Class	Data base Id	Data base Name	Object Id	Object Type	SPID
sales_report	SP:Cache Insert	1	master	2636 71987	8272 - P	58

When a stored procedure is executed for the first time, the SP:Cache Insert event is fired and the text data of the trace event contains the stored procedure name, and not the entire body of the stored procedure. Notice that in this case too the SP:Cache Miss event is not fired. The object ID in this case is that of the stored procedure as reported in sys.objects.

Now let us consider an example where we will fire the SP:Cache Miss Event:

create table t1(col1 int primary key, col2 int, col3 int)

go

TextData	Event Class	Data base Id	Data base Name	Object Id	Object Type	SPID
create table t1(col1 int primary key, col2 int, col3 int)	SP:Cache Miss	1		6993 70779	20801 - AQ	58

Certain DDL statements are not cached e.g. create table DDL. When the create table DDL is executed, we fire the SP:Cache Miss event because we are sure that it will not be followed immediately by a SP:Cache Insert event.

There are 2 conditions under which a compiled plan is removed from cache: memory pressure or procedure cache flush. In both these cases we fire the SP:Cache Remove event. In SQL Server 2005 we distinguish these two by providing different eventsubclasses for them: 1 - Compplan Remove, 2 - Proc Cache Flush. To help identify database operations flushing the plan cache in SQL Server 2005 SP2 an Errorlog event is fired with the following text data: "SQL Server has encountered %d occurrence(s) of cachestore flush for the '%s' cachestore (part of plan cache) due to some database maintenance or reconfigure operations". Note that the event if fired in 5 minute intervals as long as there was a cache flush operation in that time interval. For example:

dbcc freeproccache

go

TextData	Event Class	Event Sub Class	Data base Id	Data base Name	Object Id	Object Type	SPID
Entire Procedure Cache Flushed	SP:Cache Remove	2 - Proc Cache Flush	1	master			58

Consider a case we query a table in an auto-close database which results in plan cache flush:

alter database test_db set auto_close on

go

select * from test_db.dbo.test_table

go

TextData	Event Class	Event Sub Class	Data base Id	Data base Name	SPID
Entire Procedure Cache Flushed	SP:Cache Remove	2 - Proc Cache Flush	1	master	18
2006-12-31 16:17:13.93 spid61      Setting database option AUTO_CLOSE to ON for database test_db.	ErrorLog		1	master	61
2006-12-31 16:17:14.24 spid18s     SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.	ErrorLog		1	master	18
2006-12-31 16:17:14.24 spid18s     SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'SQL Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.	ErrorLog		1	master	18
2006-12-31 16:17:14.24 spid18s     SQL Server has encountered 1 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.	ErrorLog		1	master	18

The SP:Cache Hit event is fired when we find the compiled plan and/or the MXC in the cache for query submitted for execution. If we find the MXC in the cache from previous execution, then we will fire SP:Cache Hit event with eventsubclass: 1- Execution Context Hit. For example:

select * from t1 where col1 = 5;

go

select * from t1 where col1 = 5;

go

In this case, the after the first query is compiled the parameterized query is inserted into the cache. After query execution the execution context is as cached as well. Since the exact same query is re-executed and the execution context was cached, we get an execution context cache hit event.

TextData	Event Class	Event Sub Class	Data base Id	Data base Name	Object Id	Object Type	SPID
(@1 tinyint)SELECT * FROM [t1] WHERE [col1]=@1	SP:Cache Insert		1	master	2573 0849	20816 - PQ	58
select * from t1 where col1 = 5;	SP:Cache Insert		1	master	5610 17432	20801 - AQ	58
select * from t1 where col1 = 5;	SP:Cache Hit	1 - Exec ution Context Hit	1	master	5610 17432	20801 - AQ	58

If the MXC has been deleted due to memory pressure, or it was never cached, or if its not locally available on the same node in a multi-node machine, then we just fire the SP:Cache Hit event with Eventsubclass 2- Compplan Hit. For example:

select * from t1 where col1 = 5;

go

select * from t1 where col1 = 6;

go

In this case after the compilation of the first query the parameterized query is cached and this fires the cache insert event. For the second query in the batch we have a cache hit for the compiled plan but not an execution context hit since the parameter values are different in the second query.

TextData	Event Class	Event Sub Class	Data base Id	Data base Name	Object Id	Object Type	SPID
(@1 tinyint)SELECT * FROM [t1] WHERE [col1]=@1	SP:Cache Insert		1	master	2573 0849	20816 - PQ	58
(@1 tinyint)SELECT * FROM [t1] WHERE [col1]=@1	SP:Cache Hit	2 - Comp plan Hit	1	master	2573 0849	20816 - PQ	58

The SP:Recompile and SQL:StmtRecompile trace event is discussed in this whitepaper . The plan cache related trace events and their different eventsubclasses can be found using:

select distinct * from sys.trace_subclass_values

where trace_event_id in (34, 35, 36, 37, 38)

and trace_column_id = 21

order by trace_event_id, subclass_value

go

Trace_ event_ id	Trace_ column_ id	Subclass_ name	Subclass_ value
36	21	Compplan Remove	1
36	21	Proc Cache Flush	2
37	21	Schema changed	1
37	21	Statistics changed	2
37	21	Deferred compile	3
37	21	Set option change	4
37	21	Temp table changed	5
37	21	Remote rowset changed	6
37	21	For browse permissions changed	7
37	21	Query notification environment changed	8
37	21	PartitionView changed	9
37	21	Cursor options changed	10
37	21	Option (recompile) requested	11
38	21	Execution Context Hit	1
38	21	Compplan Hit	2

12.2 Performance Counters

Plan cache counters defined in SQL Server 2005 include Cache Hits Ratio, Cache Pages, Cache Objects Count, and Cache Objects in Use. Plan cache performance counters in SQL Server 2005 are available under the performance object ‘SQLServer: Plan Cache’.  The plan cache performance counters have one instance for each of five cache stores: Bound Trees, Extended Stored Procedures, Object Plans, Sql Plans and Temporary Tables and Table Variables and one additional _Total instance. In other words, in SQL Server 2005 we now report hit ratio, cache pages, object counts etc per cache store instead of the individual types of cached objects.

Examine the SQL Plans and Object Plans instances of the Cache Hit Ratio counter to see if compiled plans are being re-used. Low cache hit ratio (<20%) along with a sustained query execution rate (SQLServer: SQL Statistics\Batch Requests/sec) indicates that compiled plans are not being re-used. It should be noted that the hit ratio counter may be skewed by internal lookups performed.

The Cache Pages counter is useful counter to watch when performance degradation observed on the server. For a workload with adhoc queries, typically the database pages increase along with the plan cache pages. It in SQL Server 2005 RTM And SP1 since the plan cache can grow to about ~80% of the buffer pool without being under memory pressure, this would leave very little room for database pages. This results in the database pages being evicted and subsequent performance degradation. To verify if this is indeed what is happening track the following performance counters: 'SQL Server: Plan Cache\Cache Pages(_Total)' and 'SQLServer: BufferManager\Database pages' and look for a significant decrease in the database pages counter as the plan cache pages counter increases and reaches the threshold value after which memory pressure sets in. This problem has been addressed in SQL Server 2005 SP2 by limiting the cache store sizes (more details will be available in blog post titled ‘Improvements made to Plan Cache behavior in SQL Server 2005 SP2’). Other potential solutions would be to reduce the amount of caching by examining the workload to see if queries have been parameterized, or can be rewritten with stored procedures.

Other performance counters that provide useful plan cache related information include SQL Server:SQL Statistics\Unsafe Auto-Params/sec. An increment in the SQL Server:SQL Statistics\Unsafe Auto-Params/sec performance counter indicates that the query was unsafe auto-parameterized. Likewise the counters SQL Server: SQL Statistics\Forced Parameterizations/sec and SQL Server: SQL Statistics\Safe Auto-Params/sec give then rate of forced parameterizations and safe auto parameterizations.

The counters SQLServer: SQL Statistics\SQL Compilations/ sec and SQLServer: SQL Statistics\SQL Re-Compilations/ sec give the number of compilations and recompilations per second. In order to benefit from caching, ideally the rate of compilations and recompilations should be low.

One additional thing to note here is that queries compiled with a RECOMPILE hint are not actually considered recompiles. The word recompile in these hints is a misnomoer because the new plan is generated before query execution begins these would more accurately be classified as compiled and not recompiles. Hence we see an increment in the SQL Server:SQL Statistics\SQL Compilations/sec counter and not the SQL Server: SQL Statistics\SQL Re-compilations/sec counter. Consider the example below: Sales table has three columns: transaction id, country id, and total_amount. We also know that majority of the sales occur in country with id = 1, and country with id = 2 has far fewer rows in the sales table. If we had a stored procedure that reported sales by country id as below:

create proc sales_report @country_id int

as begin

select * from sales where country_id = @country_id

end

go

If we now executed the stored proc with country id 2 first, then the query_plan chosen based on parameter sniffing is a sub-optimal plan for country id 1. To avoid parameter sniffing, we could adopt one of three approaches:

Approach 1: Create the procedure by adding WITH RECOMPILE to stored procedure definition as below.

create proc sales_report @country_id int with recompile

as begin

select * from sales where country_id = @country_id

end

go

Before taking approach one, evaluate if the compilation time of the stored procedure is relatively small because this approach would mean compilation of all queries inside the stored procedure. Also the compiled plan is not inserted into cache.

Approach 2: Add the WITH (RECOMPILE) hint to the query inside the stored procedure

create proc sales_report @country_id int

as begin

select * from sales where country_id = @country_id option (recompile)

end

go

Before taking approach two, evaluate if additional compilation time of the query relative to the execution time savings is relatively small then this approach is may provide the more suitable solution.

Approach 3: Execute the stored procedure WITH RECOMPILE.

Approach 3 implies a new plan will be compiled for every execution of the stored procedure. The compiled plan generated will not be inserted into cache. However, a previously cached plan for the stored procedure will not be removed.

exec sales_report @country_id = 2 with recompile

go

For all three approaches, the compilations counter is incremented, and not the recompilations counter.