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. 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.
