How to find out which Queries have non-reusable Query Plans?

Following a post on Stack Exchange asking how to check if a Query Plan of an SQL statement was compiled/re-compiled or cached for the first time, I was driven to write a more detailed explanation on this.

This query will update 1000 rows.

Update t1 set c1 = 10

If I execute it for the first time, SQL needs to create first a Query Plan for it, Compile it and store it in the SQL plan cache for the first time. This will be used for next executions. Plan re-use is desirable for OLTP workloads because re-creating the same plan (for similar or identical transactions) is a waste of CPU resources. What if, the Plan is not cached long enough and each time we execute the Update SQL creates the same Query Plan and compiles it over and over again? This is a performance problem that must be analysed. How we find these queries with many Query Plans compilations?

Profiler is my best friend, along with Performance Monitor when analyzing Poor Queries.

To find out how many compilations SQL Server is doing, you can monitor the SQLServer: SQL Statistics: SQL Compilations/Sec counter. This counter measures how many compilations are performed by SQL Server per second. To have a better undarstanding monitor also SQLServer: SQL Statistics: Batch requests/Sec and SQLServer: SQL ReCompilations/Sec counters.

Performance Monitor – SQL Compilations counters

A general acceptance is that if SQL Compilations/Sec counter measures over 100 compilations per second, then you may be experiencing  unnecessary compilation overhead.

Some of the reasons when Query Compilation/Re-compilation occurs:

– Changes in Object Schema

– Index rebuild, drop, create

– Update Statistics

– Stored Procedure alter – can’t use the old Query Plan.

As well Batch requests/Sec should be compared with the SQL Compilations/Sec. Say I have 500 Batches per sec and my Compilation rate is at 200/sec. It is close to 50% of all batches. So it is good to have a compilation rate as low as possible.

So, the rate only shows that the system is high on Compilations but how to know which queries are not cached?

Profiler can be used to find this out. I will explain here how to extract data from Profiler testing the Performance of a known SQL Statement but you will probably wish to find what query is getting compiled over and over again. The results can be overwhelming and hard to filter. I suggest you store your results into a table to a different database (I use a different SQL instance as well) than the one you are monitoring. It will allow you to select all the Events for a single SPID. The SPID will be easy to extract from Profiler.

Below are described the steps to catch the Poor Queries for which the Query Plan is Compiled more often that it needs to.

STEP 1:

To check out the IO and Execution time enable statistics output:

set statistics time on
set statistics io on

STEP 2:

Start a Profiler new trace and include following events:

  • Performance
    • Performance Statistics – Indicates that a compiled plan was cached for the first time, re-compiled or evicted from plan cache.
  • Stored Procedures
    • RPC:Completed
    • SP:CacheHit – Indicates when a procedure is found in cache.
    • SP:CacheInsert – Indicates when an item is inserted into procedure cache.
    • SP:CacheMiss – Indicates when a Stored Procedure is not found in the procedure cache.
    • SP:CacheRemove – Indicates when an item is removed from procedure cache.
    • SP:Recompile – Indicates that the Stored Procedure is recompiling.
  • TSQL
    • SQL:BacthCompleted
    • SQL:BatchStarting

Check to Show All Columns and select each column for Performance Statistics event. Click Run.

MY EXAMPLE:

To achieve this post goal I removed all elements from plan cache for testing purposes (!!! never do this on Production !!!)

dbcc freeproccache
go
dbcc dropcleanbuffers
go

After Starting Profiler –> I will run below query:

set statistics time on
set statistics io on
Update t1 set c1 = 10

STEP 3:

Let it run for some time (10 min) and then identify the SPID of the rows where Performance Statistics, SP:CacheMiss and SP:CacheInsert are displayed. Filter those SPID’s that contain all of three Events.

Now you identified basically those Processes SPID for which the Query Plan was not found in the cache, compiled and inserted in the cache.

MY EXAMPLE:

Execution Output:

SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 90 ms.
SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 0 ms.
Table 't1'. Scan count 1, logical reads 17738, physical reads 3, read-ahead reads 1000, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

 SQL Server Execution Times:
   CPU time = 234 ms,  elapsed time = 2454 ms.

(1000 row(s) affected)

Profiler Output:

Profiler – Stored Procedure not in cache

First indication that the query is not cached is given by first occurence of Performance Statistics event class, that has a duration of 86 ms used to compile the statement within an adhoc query (EventSubClass: 2 – Batch:Plan). To see all types of EventSubClass descriptions, look here at msdn documentation. Afterwards, SQL checks whether the statement exists in procedure cache – SP:CacheMiss shows that it is not there. The statement is inserted into the procedure into procedure cache : SP:CacheInsert. The actual duration of the statement is 2544 ms. In SQL statistics we can see a difference between the time reported for compilation 90 ms (IO statistics) against 86 ms (Profiler)

STEP 4:

I will execute again the Update after it was cached to see the difference.

Profiler – Stored Procedure found in cache

I no longer have Performance Statistics event class occurrence – so the compiled plan was found in the cache. Moreover I see a new event SP:CacheHit which confirms that the Query Optimizer found the Statement in procedure cache. It is obvious also the difference in Duration: 1223 ms. versus 2544 ms. Same reads and writes which is normal. CPU usage: 171 versus 234.

So the SQL physical resources are less used when query plan does not have to be compiled again. It is an important fact when designing web applications as well as writing SQL code. The DBA should be able to report excessive SQL Compilations and work with the DEV team to try to cache as much as possible.

Some good documents on this subject can be found also here:

http://www.sql-server-performance.com/articles/per/optimizing_sp_recompiles_p1.aspx

http://www.mssqltips.com/tip.asp?tip=1661

http://technet.microsoft.com/en-us/library/cc293623.aspx

http://www.sql-server-performance.com/tips/sql_server_performance_monitor_coutners_p1.aspx

  1. I see you put a lot of effort in your site, keep writing!

  2. Thank you Vern, keep following my blog… I try to post as often as I can.

  3. Hello would you mind letting me know which webhost you’re using? I’ve loaded your blog in 3 completely different internet browsers and I must say this blog loads a lot faster then most. Can you suggest a good internet hosting provider at a fair price? Thank you, I appreciate it!

  4. Running the profiler almost kills my server, can we not get number of compiles from sql_handle or something? Are all statistics just about the queries in cache?

    BTW: good article, thnx for sharing.

  5. Good article, helped me alot

Leave a Comment


NOTE - You can use these HTML tags and attributes:
<a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>