Scripting Traces for Performance Monitoring on SQL Server - Page 2

Creating the Trace Script

To create the trace, fire up SQL Profiler and use it to define the trace. You do not have to do anything special to create the trace but completing a few fields in the GUI makes life easier. Normally, when you use the Trace Properties Form to ask that the trace sent to a file and not to SQL Profiler's screen, you select a "server trace." Do that and fill in a file name when it asks. You should use the fields at the bottom of the General tab to "Enable trace stop time" and fill in a time. Do not worry what time to stop at; it will be changed when the stored procedure is created.

Figure 1 shows the General tab as I used SQL Profiler to create the trace. I started with the SQLStandard.trc trace template and specified "Save to file" and a trace stop time.

Figure 1 SQL Profiler's General Tab

The actual contents of the other tabs are not critical to understanding the scripting technique because when SQL Profiler creates the script, it is going to add the events, data columns and filters that you ask for. In this case, among other things, I am looking for table scans, lock deadlocks and statements that take over 100 milliseconds to execute.

There is a little bit of a trick to setting up the filter: all conditions are combined with the AND operator. That is, the trace only records an event when all the expressions in the filter are satisfied. To make sure that the script does not filter out too much, I have used a 100-millisecond filter on duration, not CPU time because deadlocks do not consume CPU, they just make a query run until the deadlock timeout.

Once you are satisfied with the definition of the trace, run it, stop it and then use SQL Profiler's menu command File -> Script Trace -> For SQL Server 2000. When asked, give it a file name to save the script. The following listing shows the first few lines of the output:

/****************************************************/
/* Created by: SQL Profiler                         */
/* Date: 07/14/2003  04:29:56 PM         */
/****************************************************/


-- Create a Queue
declare @rc int
declare @TraceID int
declare @maxfilesize bigint
declare @DateTime datetime

set @DateTime = '2003-07-14 18:29:20.000'
set @maxfilesize = 5
exec @rc = sp_trace_create @TraceID output, 2
           , N'\\NSL2\Projects\Article2.trc', @maxfilesize, @Datetime
if (@rc != 0) goto error

-- Client side File and Table cannot be scripted

-- Set the events
declare @on bit
set @on = 1
exec sp_trace_setevent @TraceID, 10, 1, @on
exec sp_trace_setevent @TraceID, 10, 12, @on
exec sp_trace_setevent @TraceID, 10, 13, @on

SQL Profiler creates a script that duplicates the trace that you specified using the GUI screens.

The script to add all the events and columns to the trace runs on for several pages and there is no need to look at more than the first few lines. However, it's a script, or batch, not a stored procedure. There is some work to turn it into a more usable form. That's the next task. These are the requirements:

• Turn the script into a stored procedure that can be run at any time.
• The proc should take the duration to run the trace.
• Create an output file name that is sure to be unique.
• Set the trace end time based on the current time and the duration that is requested.

All three parts are pretty easy. I name the stored procedure dba_Trc_Northwind1 to distinguish it from any other traces that I might be running. Creating a unique file name based on the time is not particularly difficult either. To insure uniqueness put the date and time into the file name in a form that is both a valid file name, one without colons or slashes, and one that sorts based on the date and time. I have used a UDF, udf_DT_FilenameFmt, from my library to form the name. You can get the UDF from a recent issue of my T-SQL UDF of the Week newsletter at this URL: http://www.novicksoftware.com/UDFofWeek/Vol1/T-SQL-UDF-Volume-1-Number-36-udf_dt_filenamefmt.htm.

After adding the stored procedure header and the code to calculate the end time, the top of the trace looks like the listing that follows. The shaded area calculates the file name and trace stop time before calling sp_trace_create to begin the process that defines the trace.

CREATE PROCEDURE dba_Trc_Northwind1 

    @Sec int = 600 -- Duration in seconds for the trace
  , @TraceID int OUTPUT -- Return the TraceID to the caller.
  WITH RECOMPILE
/*
* Creates a trace on the Northwind database.
***********************************************************************/
AS 
declare @rc int
declare @dbaTraceID int
declare @maxfilesize bigint
declare @DateTime datetime
DECLARE @FileName nvarchar(256)
      , @StartDT  datetime -- When the trace started

SELECT @StartDT = getdate()
SELECT @FileName = N'\\NSL2\Projects\Northwind1-' 
                 + dbo.udf_DT_FileNameFmt (getdate(), 1, 1) 

     , @DateTime = DATEADD (s, @Sec, @StartDT)
     
set @maxfilesize = 5
exec @rc = sp_trace_create @TraceID output, 2, @FileName
                                , @maxfilesize, @Datetime

if (@rc != 0) goto error

-- Set the events
declare @on bit
set @on = 1
exec sp_trace_setevent @TraceID, 10, 1, @on
exec sp_trace_setevent @TraceID, 10, 12, @on

Later in the day, when activity has died down, the trace file will be loaded into a table for analysis. To facilitate that process and for keeping track of the traces, the file name, start time, person responsible, and a comment for each trace is recorded in the table dbaTrace. Here is the script to create it:

CREATE TABLE dbo.dbaTrace (
    dbaTraceID int IDENTITY (1, 1) NOT NULL ,
    TraceID int NOT NULL ,
    StartDT datetime NOT NULL ,
    EndDT datetime NOT NULL ,
    [FileName] nvarchar (255)  NULL ,
    FileLoadedDT datetime NULL ,
    Responsible nvarchar (128)  NULL ,
    Description nvarchar (255)  NULL 
  , CONSTRAINT dbaTrace_PK PRIMARY KEY CLUSTERED 
                (dbaTraceID)
) ON [PRIMARY]
GO

The bottom portion of the stored procedure takes care of inserting a row in the dbaTrace table by calling the stored procedure dba_Trc_Record. There is the last dozen or so lines of dba_Trc_Northwind1:

-- Set the trace status to start
exec sp_trace_setstatus @TraceID, 1

-- display trace id for future references
-- select TraceID=@TraceID

EXEC @RC = dba_Trc_Record @Filename, @StartDT, @Sec, 'Andy'
                , 'Scripted Trace for Northwind scans and deadlocks'
                , @TraceID, @dbaTraceID OUTPUT

PRINT 'Recording Started.  SQL Trace ID=' 
                          + CONVERT(varchar(9), @TraceID)
PRINT 'dbaTrace.dbaTraceID = ' 
                          + CONVERT(varchar(9), @dbaTraceID)
goto finish

error: 
select ErrorCode=@rc

finish: 

Since this stored procedure is going to be invoked by a SQL Job, PRINT statements are the way to get information into the log of the Job step that invokes it. That is why I commented out the "select TraceID=@TraceID" statement. Instead, the two PRINT statements in the shaded area show SQL Server's ID for the trace and dbaTraceID, which is the key to the dbaTrace table.

The job is real simple. Just one step that invokes dba_Trc_Northwind1 and supplies the number of seconds for the trace: Here's the text of the only step:

DECLARE @rc int, @dbaTraceID int
exec @rc = dba_Trc_Northwind1 600, @dbaTraceID OUTPUT
PRINT 'RC from starting Trace = ' + convert(varchar(9), @rc)
PRINT 'DBA TraceID = ' + convert(varchar(9), @dbaTraceID)

I have used 600 seconds for 10 minutes of monitoring. During a period of heavy activity, that seems to be sufficient.