Tracing Stored Procedures

One of the great things about stored procedures is that you
can put a whole bunch of different commands into one procedure, and call
everything with a single command.  Gnarly!  However, if the procedureruns slowly, it’s difficult to determine
which command(s) are the problem.  Bogus!

One trick I use is to sprinkle little logging steps
throughout my stored procedure, and try to narrow down which command is causing
the problem.  These steps just log a step name and a timestamp into a
table.

My table has the following structure:

CREATE TABLE [tblCommands] (
 [fldID]
[int] IDENTITY (1, 1) NOT NULL ,
 [fldCommand] [nvarchar] (2000)
COLLATE SQL_Latin1_General_CP1_CI_AS NULL ,
 [fldDate] [datetime] NOT
NULL CONSTRAINT [DF_tblCommands_fldDate] DEFAULT (getdate())
) ON
[PRIMARY]
GO

fldCommand is either a good name of the setp being logged,
or something descriptive about what’s happening in the procedure.  Just so
long as I can find it again in the sproc.

Then, I add commands such as

insert into tblCommands(fldCommand, fldDate)
values (‘Final selection’,getdate())

— do my selection here

insert into tblCommands(fldCommand, fldDate)
values (‘End’,getdate())

Reviewing the data from
tblCommands:

fldID      
fldCommand        
fldDate
———– —————-  
———————–
31         
Start             
2006-05-11 13:18:19.943
… (snipped for
brevity)
39          Final
selection    2006-05-11 13:18:24.240
40         
End               
2006-05-11 13:19:56.677

We can see that the entire procedure runs in roughly 1:40,
with approx. 1:30 of that wrapped up in the final selection step alone.  By
focusing on only the final step, I was able to optimize the query so that the
entire procedure runs in 10 seconds.

I realize that with the naming convention I’ve used here,
I’m likely to raise the ire of naming zealots.  I like appending a prefix
to column names because that means I can use a reserved word such as ‘Date’ as a
column name.  If you don’t like it, you’re fere to use a different
convention in your own sprocs.

<update 2005-05-14>

Eric brings up a good
point in his comment below about using the Query Analyzer (part of the SQL
Server 2000 tools).  I have used the Query Analyzer extensively, and one
place it falls short is with dynamic SQL statements in your queries.  If
you have properly formatted dynamic sql (see http://www.rjdudley.com/blog/Is+Dynamic+SQL+In+Your+Stored+Procedures+Vulnerable+To+SQL+Injection.aspx),
and especially more than one dynamic SQL statement, the Query Analyzer can’t
analyze the sproc.  Adding sinks like I have above can help debug an entire
sproc, especially those with dynamic SQL.