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.
»
See All Articles by Columnist Andrew Novick
» 
IE 7
Firefox 2.0
Comment and Contribute
