Month: May 2006

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.

Part of my work involves a SQL Server 2000 data warehouse,
updated nightly with extracts from an ERP system.  I knew that the DTSs
tended to run long, and I wanted to get a better idea of exactly how much data
we were moving around.

First thing I did was add a table with the following
schema:

CREATE TABLE [tblDtsLog]
(
 [fldEntry] [int] IDENTITY (1, 1) NOT NULL ,
 [fldStep]
[int] NOT NULL ,
 [fldStepType] [varchar] (5) COLLATE
SQL_Latin1_General_CP1_CI_AS NOT NULL ,
 [fldStepName] [varchar] (50)
COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
 [fldTimeStamp]
[datetime] NOT NULL ,
 [fldNotes] [varchar] (255) COLLATE
SQL_Latin1_General_CP1_CI_AS NULL ,
 [fldPackage] [varchar] (50)
COLLATE SQL_Latin1_General_CP1_CI_AS NULL
) ON
[PRIMARY]

This is a pretty general structure, and allows me to
add different logging and debugging steps to the DTS.  fldEntry is simply
an incrementing value to help sorting what happened when.  fldStep refers
to the stepf of the DTS package, fldStepType is a short description of the DTS
step.  I use fldStep because someone always asks me what that step is doing
when we’re looking at the numbers, and it’s easier to log it than open the DTS
and find it.  fldStepName is there because I inherited almost all of these
DTSs, and the names don’t always describe what’s going on.  fldTimeStamp is
the execution time of the step, fldNotes are some information I want to include
about the step (usually just a rowcount), and fldPackage is the name of the DTS
package.

One of the early steps for most DTSs is the extract
from the ERP system to an intermediate table.  Depending on the package,
the data in the intermediate table used for comparisons or modified before being
migrated to the production tables.  By adding  a SQL task immediately
after the extract, I could get an exact idea of how many data rows we just
moved:

select * from IntermediateTable
insert
into tblDtsLog(fldStep, fldStepType, fldStepName, fldTimeStamp,fldNotes,
fldPackage) values (1,’Begin’, ‘Extract Step 1’,getdate(),@@rowcount, ‘Some
DTS’)

This simly adds one entry to the above table with a
count of how many rows exist in the intermediate table.   For other steps, I use the Begin and End flags in conjunction with
the getdate() to see how much time elapsed for the processing of a particular
matching or modification step.  By sprinkling these liberally through my
DTSs (some packages have 15-20 of these logging sinks in them), I have excellent
insight into what is running slow, and then we can examine each step and try to
optimize it.

Recently, we used the results of this monitoring to
make a small tweak to one step of one DTS, which resulted in an overall gain of
2 hours of processing time in the overall update!

Freaky–we were just talking about this yesterday afternoon.

The latest SQLServerCentral.com
update came out today, and the lead story is an update to an older article
titled “Copying
DTS Packages to a Different Server“.  The article has some code samples
to show you how you can copy DTS packages from one SQL Server 2000 to
another.

If you’re lazy, don’t bother with the code.  Instead, there’s a great
GUI tool called DTSBackup
2000 from SQLDTS.com.  Using
DTSBackup 2000 couldn’t be easier–choose your origin server (supply
credentials if necessary), choose the DTSs you want to copy, choose your
destination server (supply credentials if necessary), add in the owner pwd if
necessary, and click Transfer.  Within minutes, your packages are
transferred.  It’s sweet, and works like a charm.

I use this to copy DTSs from my dev/test server to the prod server, and back
again if necessary.  Layout in the visual designer gets a little goofy, but
that’s the only downside.