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.