12.0 Plan Cache Trace Events and Performance Counters



 


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.