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.

One thought on “Tracing Stored Procedures”

  1. You were just waiting for me to say something, and then you took it away! šŸ™‚

    Have you used the Show Execution Plan in Query Analyzer? Your way provides better real statistics, but requires a little bit of work to set up…

Comments are closed.