Identifying Stored Procedure Recompilation Problems in SQL Server 2000

Monday May 12th 2003 by Andrew Novick
Share:

Andy Novick discusses the reasons that SQL Server 2000 decides to recompile a stored procedure and demonstrates the tools and techniques that you can use to monitor recompilation. Read the article, watch the movie!

Around 1980 when relational databases and I were both young, I was told that the time to parse the SQL statement and create the search plan took about 50 percent of the time required to execute a SQL query. Most of this was consumed by CPU time for parsing and plan creation. The other 50 percent was devoted to executing the query. Then as now, execution time was primarily consumed by I/O for reading the pages required to satisfy the query. With computer CPUs being about 30,000 times faster today than they were in 1980 you'd think that parsing and plan creation would no longer involve significant effort. But they do.

That is not to say that the time spent in compilation and plan creation isn't worth the effort. It is. SQL Server 2000 uses a far more sophisticated algorithm for creating plans then databases did in the past. Its algorithm is cost based instead of schema based. That means it uses knowledge about the actual values in the columns being searched to pick the plan that will most likely result in the fewest I/O operations. The fewer the I/O operations, the faster the query runs. In SQL Server, the knowledge about columns is stored as column statistics.

When SQL Server executes a stored procedure for the first time, it creates an execution plan. The plan is a set of instructions on how to execute the query and the process of creating the plan is referred to as compilation. Plans are stored in the procedure cache, which is in the dynamic table master..syscacheobjects. The next time the stored procedure is used, the plan can be retrieved from cache and it doesn't have to be re-created. That is, unless there is a reason that the existing plan was removed from the cache or that the plan can no longer be used. In these cases, the plan must be recompiled.

At times SQL Server can spend excessive time in recompiling stored procedures. Because stored procedures have to be locked during recompilation, excessive recompilation can slow a system down out of proportion to the amount of CPU consumed. It has become a problem in many systems.

This article discusses the reasons that SQL Server 2000 decides to recompile a stored procedure and demonstrates the tools and techniques that you can use to monitor recompilation. In another article next month, I'll discuss what can be done to minimize recompilation. If your system makes extensive use of stored procedures, minimizing recompilation can give you an important boost in performance.

Reasons that a stored procedure will recompile

SQL Server 2000 recompiles a stored procedure for many reasons. The first group of reasons that cause recompiles are:

  • requests to recompile an individual procedure
  • Requests to recompile procedures that depend on a database object, such as a table or view
  • Actions that result in the recompilation of all procedures.

In explicit SQL Server terms these reasons are:

  1. Use of the WITH RECOMPILE option on the CREATE PROC or ALTER PROC statement. The May 6th issue of my T-SQL UDF of the Week Newsletter has an article about how to detect which procedures were created with the WITH RECOMPILE option and has a user-defined function that lists all such procedures. http://www.novicksoftware.com/UDFofWeek/Vol1/T-SQL-UDF-Volume-1-Number-25-udf_Proc_WithRecompile.htm

  2. Executing the system stored procedure sp_recompile on the procedure or on a table or view that the procedure depends on.

  3. Use of the WITH RECOMPILE option on the EXEC statement

  4. Use of DBCC FREEPROCCACHE

These reasons are fairly easy to fix. Next month's article has a section on how to locate these easily, and gives some methods for minimizing them when they are really necessary.

The next group of reasons that recompilation occurs is because a change has occurred in a database or database object that invalidates the cached execution plan. These reasons are:

  1. Restoring the database containing the procedure or any of the objects that the procedure references. Most often, this involves restoring a database that is referenced by the stored procedure.

  2. A schema change in any of the objects that are referenced by the procedure. This includes the addition or alteration of a column, constraint or index on a table or view referenced by the procedure.

  3. Statistics Change. These can be automatically generated by SQL Server or requested with the CREATE STATISTICS or UPDATE STATISTICS statements.

Restoring a database usually will not wait. You will just have to live with any recompiles caused by restores. Schema changes should be scheduled for off hours when any recompiles caused have minimal impact. Statistics changes can happen automatically if the database option 'auto create statistics' is on. Automatic update of statistics was a major issue in version 7 because, when working on temporary tables, SQL Server would recalculate statistics, and therefore recreate the plan, after only five modifications to a temporary table. SQL Server has an improved algorithm for automatic updating of statistics. If this is the reason for recompilations, you may want to consider turning off the automatic generation of statistics.

Memory constraints cause the next reason:

  1. The plan being aged out of cache.

If this is occurring frequently, you should address the overall memory requirements of the SQL Server instance.

The final two reasons occur in the executing stored procedure. They are the causes that are most amenable to better programming:

  1. Interleaving Data Definition Language (DDL) and Data Manipulation (DML) operations. Execution of DDL statements, such as the creation of permanent or temporary tables and indexes on tables, forces a recompile at the next DML statement, such an INSERT, UPDATE, or SELECT.

  2. Using one of these SET statements to change a connection option:
  • SET ANSI_DEFAULTS
  • SET ANSI_NULLS
  • SET ANSI_PADDING
  • SET ANSI_WARNINGS
  • SET CONCAT_NULL_YIELDS_NULL

Because these two reasons cause most of the recompiles, I consider the problem pretty fixable. It is a matter of modifying the logic of your stored procedure to be more aware of what causes recompiles. The stored procedure shown next causes several compiles due to interleaved DDL and DML and use of SET statements.

SET QUOTED_IDENTIFIER ON
SET ANSI_NULLS ON 
GO

CREATE PROCEDURE dbo.usp_Recompiles_SeveralTimes AS 

SET NOCOUNT ON -- Doesn't cause a recompile

-- Cause a recompile due to creation of the temporary table   
CREATE TABLE #Temp1 ([id] int identity (1,1)
                   , [name] varchar(64))
INSERT INTO #Temp1 ([name]) VALUES ('Gregor Samsa')

-- Cause a recompile because of a change in a session option
SET ANSI_NULLS OFF
INSERT INTO #Temp1 ([name]) VALUES ('Padme Amidala')

-- Cause a recompile because of a change in a session option
SET ANSI_WARNINGS OFF
INSERT INTO #Temp1 ([name]) VALUES ('Casper Guttman')

-- Cause a recompile because of a new index
CREATE CLUSTERED INDEX IDX_Name ON #Temp1 ([name])
SELECT * FROM #Temp1 ORDER BY [name]

DROP TABLE #Temp1 -- Doesn't Cause a recompile
GO

We will use this stored procedure as an example for how to monitor and diagnose recompiles in the next section.

Tools to Monitor Recompiles

There are two tools available from Microsoft to monitor recompiles: Windows Performance Monitor and SQL Server Profiler. Windows Performance Monitor, or PerfMon, monitors compiles and recompiles in the aggregate. It is a good tool to use when you are determining the overall frequency of recompiles.

SQL Server Profiler gives you a detailed picture of the stored procedures that are executing and shows you exactly where recompiles are occurring. However, it can produce voluminous output and must be used carefully.

Using PerfMon to Gather Aggregate Recompile Statistics

The Perfmon video

When SQL Server is installed, it adds its own performance counters to PerfMon. If you install multiple instances of SQL Server on the same computer, each instance has its own counters. The most interesting counters to watch when monitoring recompiles are in the Performance object named "SQL Server:SQL Statistics". The counters to monitor are "SQL Compilations/sec" and "SQL Re-Compilations/sec." Figure 1 shows PerfMon's Add Counter dialog box as "SQL Re-Compilations/sec" is added to the list of running counters.

Figure 1 Adding SQL Re-Compilations/sec to PerfMon

Once the counters are added to PerfMon's current list, monitoring begins. In order to generate enough recompile events, I'm going to use this script to generate one hundred invocations of usp_Recompiles_SeveralTimes.

DECLARE @i int, @rc int
SET @i = 1
WHILE @I <= 100 BEGIN
    EXEC @RC = usp_Recompiles_Due2Index  
    SET @I = @I + 1
END

When I run the script the counts of compiles and recompiles in PerfMon spike near the 100/second mark. Figure 2 shows PerfMon after I ran the script 3 consecutive times.

Figure 2 PerfMon showing 100s of Recompiles

The lines for SQL Compilations/sec and SQL Re-compilations/sec are running on top of each other. Compilations include recompilations but also count initial compiles when the procedure is inserted into the cache.

PerfMon shows only aggregate numbers. To get a more detailed look at the performance numbers the SQL Profiler is the best tool around.

Using the Profiler to Watch Recompile Events

The Profiler Video

The SQL Profiler captures events as they occur inside the SQL Server engine. Recompilation of a stored procedure triggers the event SP:Recompile. It is the most relevant event to monitor. There are are also related events that you will want to watch at the same time. When monitoring recompilation I suggest that you watch the events shown in Figure 3.

Figure 3 SQL Profiler Trace Properties for Diagnosing Recompiles

I have put the SQL Profiler trace definition that you can use to analyze recompilations into the file RecompileAnalysis.tdf, which you can download here. Put it into your %InstallDirectory%\80\Templates\SQL Profiler directory so that it's easy to find.

In addition to the usual Profiler data columns it is very useful to monitor the EventSubClass and I've included it in the .tdf file. When an SP:Recompile event occurs, the EventSubClass tells you the reason for the recompilation. This table shows the possible codes and their meaning.

EventSubClass

Reason for Recompilation

1

Schema, bindings, or permissions changed between compile or execute

2

Statistics changed.

3

Object not found at compile time, deferred check to run time.

4

Set option changed in batch.

5

Temp table schema, binding, or permission changed.

6

Remote rowset schema, binding, or permission changed.

When I create a profiler trace with the correct events and data columns and execute usp_Recompiles_SeveralTimes the following set of trace events is written:

EventClass

Event
SubClass

Text

Duration

CPU

Reads

Writes

SPID

TraceStart

 

 

 

 

 

 

 

SP:CacheMiss

 

 

 

 

 

 

62

SP:CacheMiss

 

 

 

 

 

 

62

SP:CacheInsert

 

 

 

 

 

 

62

SP:Starting

 

usp_Recompiles_SeveralTimes

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes SET NOCOUNT ON

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes Create Table #Temp1 (id int identity (1,1), [name] varchar(64))

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes INSERT INTO #Temp1 (name) Values ('Gregor Samsa')

 

 

 

 

62

SP:Recompile

3

 

 

 

 

 

62

SP:CacheMiss

 

 

 

 

 

 

62

SP:CacheMiss

 

 

 

 

 

 

62

SP:CacheInsert

 

 

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes INSERT INTO #Temp1 (name) Values ('Gregor Samsa')

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes SET ANSI_NULLS OFF

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes INSERT INTO #Temp1 (name) Values ('Padme Amidala')

 

 

 

 

62

SP:Recompile

4

 

 

 

 

 

62

SP:CacheMiss

 

 

 

 

 

 

62

SP:CacheMiss

 

 

 

 

 

 

62

SP:CacheInsert

 

 

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes INSERT INTO #Temp1 (name) Values ('Padme Amidala')

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes SET ANSI_WARNINGS OFF

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes INSERT INTO #Temp1 (name) Values ('Casper Guttman')

 

 

 

 

62

SP:Recompile

4

 

 

 

 

 

62

SP:CacheMiss

 

 

 

 

 

 

62

SP:CacheMiss

 

 

 

 

 

 

62

SP:CacheInsert

 

 

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes INSERT INTO #Temp1 (name) Values ('Casper Guttman')

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes CREATE CLUSTERED INDEX IDX_Name ON #Temp1 ([name])

 

 

 

 

62

SP:StmtStarting

 

insert [#Temp1___________________.....

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes SELECT * FROM #Temp1 Order BY [name]

 

 

 

 

62

SP:Recompile

 5

 

 

 

 

 

62

SP:CacheMiss

 

 

 

 

 

 

62

SP:CacheMiss

 

 

 

 

 

 

 62

SP:CacheInsert

 

 

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes SELECT * FROM #Temp1 Order BY [name]

 

 

 

 

62

SP:StmtStarting

 

-- usp_Recompiles_SeveralTimes DROP TABLE #Temp1

 

 

 

 

 62

SP:Completed

 

usp_Recompiles_SeveralTimes

160

 

 

 

62

SQL:BatchCompleted

 

usp_Recompiles_SeveralTimes

230

20

583

6

62

TraceEnd

 

 

 

 

 

 

 

As you can see, the large volume of events makes Profiler more suitable for detailed analysis than aggregate analysis. However, it is possible to capture a profiler trace to a file or a table and then perform analysis on the data after it has been gathered. This is a great strategy when you want to discover which stored procedures are recompiling most frequently. When you do this, be sure to include the ObjectID column in the trace information, you will need it to find out the name of the procedure that recompiles.

usp_Recompiles_SeveralTimes was written specifically to cause the recompiles to occur. It worked. It creates four recompiles each time it is executed. The first recompile in the above trace is caused by the creation of temporary table #Temp1. Next, the second and third recompiles are caused by use of the SET statement. The fourth recompile is caused by the creation of the index on #Temp1.

Recompiles do not occur when the SET statement or SQL-DDL is invoked, instead they occur on the next SQL-DML statement, such as a SELECT. That's while you see the same SP:StmtStarting Event on both sides of each SP:Recompile event.

Conclusion

Stored procedure recompilation can be caused by ten reasons that were listed above. The two reasons that I have found most frequently are the use of the SET statement and the use of temporary tables. The good news is that modifying the stored procedures that are frequently recompiled can cure the problem. Next month I will show you how to minimize the number of recompiles in your system by improving your stored procedures.

The Perfmon video

The Profiler Video

» See All Articles by Columnist Andrew Novick

Share:
Home
Mobile Site | Full Site
Copyright 2017 © QuinStreet Inc. All Rights Reserved