Automating Server Side Tracing in SQL Server

Note:
Information & code
samples from this article are tested on SQL Server 2005 RTM (Yukon)
and found to be working. Will update the article in case of any
compatibility issues.

Experts from within and outside Microsoft have  always said that running Profiler on a production environment is not a recommended practice, as it could degrade the performance of the server. Instead they suggest doing server side tracing via SQL Trace system stored procedures. But DBAs often questioned this by asking, what if I profile the production server, from a different PC? Well, I haven’t heard a
convincing answer to this whole thing about Profiler vs. server side tracing yet, but I attended SQL PASS 2003 in Seattle (between 11th and 14th of November, 2003). More than once during the event, some of the big wigs from Microsoft PSS recommended server side tracing over Profiler. Well, they definitely know their stuff, so I decided to start using server side tracing, instead of Profiler. Not to mention, I personally heard about incidents where DBAs brought down SQL Servers by running Profiler (especially in version 7.0).

Prior to attending PASS, I’ve never used SQL Trace system stored procedures to set up a server side trace. So, I started off by reading SQL Server Books Online. There are a bunch of SQL Trace system stored procedures, that you can use to set up a server side trace. There are also a few system functions to query and get information
about currently running traces.
Here is a list of SQL Trace system stored procedures and functions:

SQL Trace system stored
procedures

sp_trace_create Creates a trace
definition
sp_trace_generateevent Creates a user-defined
event
sp_trace_setevent Adds or removes an event
or event column to a trace
sp_trace_setfilter Applies a filter to a
trace
sp_trace_setstatus Used to start, stop and
close traces

SQL Trace system
functions

fn_trace_geteventinfo Returns information about
the events traced by a specified trace
fn_trace_getfilterinfo Returns information about
the filters applied to a specified trace
fn_trace_getinfo Returns information about
a specified trace or existing traces
fn_trace_gettable Returns trace file
information in a table format, for querying
purposes

If you look at the
documentation for above stored procedures in SQL Server Books Online, you
will realize that they accept about four input parameters each, on an
average. If you ever used Profiler, you’ll know there are numerous events
and data columns. It is a bit cumbersome To specify all those events and
data columns using these stored procedures. Because, every event has a
number associated with it, and so do the data columns. You cannot remember
all those numbers and repeatedly call the above procedures by specifying
various EventIDs and ColumnIDs. No wonder many DBAs prefer to use the
point-and-click Profiler. But hey, Microsoft is not really recommending
Profiler on a production server, and I must trace production SQL Servers
for various troubleshooting and tuning purposes while working on
bugs.

So, I decided to write my own wrapper stored procedures, that
wrap the trace system stored procedures and make it easier to setup
traces. In this article, I’ll provide you with downloadable stored
procedures, that you could use to setup your own server side traces,
without much effort. These stored procedures make the job almost as easier
as using Profiler.

For example, using my wrapper stored procedures,
you could setup and start trace, to record all stored procedures that are
called in a specified database (with database ID = 37), along with the
following information: Actual stored procedure call, start time, end time,
duration, application name and host name. As you will see below, we called
four different friendly stored procedures. To setup the same trace
directly, using trace system stored procedures, you’ll have to call at
least 10 stored procedures, one for each event traced, and one for each
data column captured. A massive saving on the number of stored procedures
called 🙂 and I am definitely finding these wrappers much easier to setup
and quicker too. The more complex the trace definition gets, the more
savings on the number of stored procedure calls.


DECLARE @TraceID int

EXEC CreateTrace
‘C:My SQL TracesAll Procedure Calls’,
@OutputTraceID = @TraceID OUT

EXEC AddEvent
@TraceID,
‘SP:Starting’,
‘TextData, StartTime, EndTime, ApplicationName, ClientHostName, DatabaseID’

EXEC AddFilter
@TraceID,
‘DatabaseID’,
37

EXEC StartTrace
@TraceID
GO

The massive saving in the
number of stored procedure calls to setup the trace, comes from the fact
that the main wrapper stored procedure accepts a list of all events and
data columns in a comma delimited string format. So, how many ever events
and data columns you want to capture in your trace, you’ll only make one
call to the wrapper stored procedure.

Better yet, all the above
wrapper procedures handle errors gracefully, and return meaningful and
helpful error messages, instead of throwing some cryptic return code
back.

An important note: Only members of the sysadmin fixed
server role can execute the SQL Trace system stored procedures. So, even
if you manage to call my wrapper stored procedures, they will fail to
invoke SQL Trace system procedures, if you are not a
sysadmin.

Deployment Instructions:

Click here to
download
the complete set of scripts in a zip file. Run all
the scripts inside a database of your choice. But make sure the tables and
stored procedures are created in the same database. I tend to create them
in a utilities/tools database created for use by the DBA team.

Now
let me introduce you to all the wrapper stored procedures I
created:

Stored procedure name Parameter usage
CreateTrace

Creates an empty trace
definition, ready for use.

Click here to
download

@OutputFile
nvarchar(245)

Specifies the trace file name and complete
path. Do not provide a .trc extension to the file name, as SQL Trace
automatically adds the .trc extension to the output
file.

@OverwriteFile – bit

Specifies whether to
overwrite the trace file, if it already exists. Default is 0, in
which case if the file already exists, an error will be raised and
trace will not be created. Specify 1 to overwrite an existing trace
file.

@MaxSize – bigint

Specifies the maximum
size in megabytes (MB) a trace file can grow upto. Default is 5 MB.
This stored procedure code restricts the maximum trace file size to
512 MB (half Giga Byte (GB)) as a safety measure, but can be
overridden by setting the variable @MaxAllowedSize to a bigger
value. You will find @MaxAllowedSize in the body of the stored
procedure.

@Rollover – bit

Specifies that when
the trace file reaches the maximum specified size, a new trace file
will be created. Default is 1, meaning new file will be created when
the current trace file reaches the maximum size. If you specify 0,
tracing will stop when the file reaches its size limit. The new file
will get the same name, but will be postfixed with a number, to
indicate the sequence. For example, when the file MyTrace.trc
reaches its maximum size, MyTrace_1.trc will be
created.

@Shutdown – bit

Defaults to 0. If you
specify 1, SQL Server will shut down, if the trace cannot be written
to the file for whatever reason. Use this option with caution, and
only when absolutely needed.

@Blackbox
bit

Defaults to 0. If you specify 1, a blackbox trace will be
created. A black box trace stores a record of the last 5 MB of trace
information produced by the server. When 1 is specified, all other
parameters will be ignored. To learn more about how black box trace
works, consult SQL Server 2000 Books Online.

@StopAt
datetime

Defaults to NULL. When NULL, the trace will run
until it is manually stopped or until the server shuts down. If you
specify a valid date and time, the trace will stop automatically at
that specified date and time.

@OutputTraceID – int –
OUTPUT parameter

This is an OUTPUT parameter and returns the
ID for the trace that is created. This ID is needed for adding
events and filters to the trace, as well as for querying the trace
definition.

Return values: -1 indicates a failure and
0 indicates success

Note: The ID of the created trace
will also be returned as a resultset for convenience.

AddEvent

Adds
events and columns to the trace definition.

Click here to download

@TraceID – int

The ID of
the trace, created by CreateTrace, and is used to identify
the trace to which to add the events and columns.

@EventList – varchar(1000)

Used to specify a
comma separated list of events to capture. You can see a list of all
valid events in the SQL Server Books Online page titled
“sp_trace_setevent”. Alternatively, you will find a list of all the
events and their descriptions, in this
script.

@ColumnList
varchar(1000)

Used to specify a comma separated list of data
columns to capture. You can see a list of all valid column names in
the SQL Server Books Online page titled “sp_trace_setevent”.
Alternatively, you will find a list of all the data columns and
their descriptions, in this
script.

Return values: -1 indicates a
failure and 0 indicates success

AddFilter

Adds filters to existing trace
definitions

Click here to download

@TraceID – int

The ID of
the trace, created by CreateTrace, and is used to identify
the trace to which to add the filter.

@ColumnName
varchar(50)

Name of the column on which to apply the filter.
You can only filter on a column, after adding that column to the
trace definition, using AddEvent

@Value
sql_variant

Specifies the value on which to filter.

@ComparisonOperator – varchar(8)

Specifies the
type of comparison to be made. Defaults to ‘=’, meaning ‘Equals’
comparison. Other valid comparison operators are: ‘<>’ (Not
Equal) , ‘>’ (Greater Than) , ‘<‘ (Less Than) , ‘>=’
(Greater Than Or Equal), ‘<=’ (Less Than Or Equal), ‘LIKE’ and
‘NOT LIKE’.

@LogicalOperator
varchar(3)

Defaults to ‘OR’. You could also specify ‘AND’.
Useful for filtering a column for multiple values.

Return
values:
-1 indicates a failure and 0 indicates
success

Note: Call this procedure once for each
filter. If you want to filter a column for a range of values
(similar to BETWEEN operator), call this procedure once with ‘>=’
comparison operator and again with ‘<=’ comparison operator.

StartTrace

Starts a specified
trace.

Click here to
download

@TraceID – int

The ID of
the trace (created by CreateTrace), to be started.

Return values: -1 indicates a failure and 0 indicates
success

StopTrace

Stops a specified
trace.

Click here to
download

@TraceID – int

The ID of
the trace (created by CreateTrace), to be stopped.

Return values: -1 indicates a failure and 0 indicates
success

ClearTrace

Clears the definition of the
trace from memory.

Click here to
download

@TraceID – int

The ID of
the trace (created by CreateTrace), to be cleared from
memory.

Return values: -1 indicates a failure and 0
indicates success

Now that
we know what the stored procedures are called and how to use their
parameters, let me show you, how to use these stored procedures to setup
traces for specific requirements. Before we go any further, here is a
quick tip. Once you setup a specific trace using my wrapper stored
procedures, you could save all those stored procedure calls in a file. Now
this file will serve you as a template, just like the Profiler
templates.

Scenario 1: Identifying long running stored
procedures

In this scenario, we will trace for all stored
procedures, that took more than 15 Seconds to complete. The output trace
file ‘LongRunningProcs.trc’ will be saved to ‘C:My SQL Traces’ (Note
that this is the location on the SQL Server machine, not the client
machine).


DECLARE @TraceID int

EXEC CreateTrace
‘C:My SQL TracesLongRunningProcs’,
@OutputTraceID = @TraceID OUT

EXEC AddEvent
@TraceID,
‘SP:Completed’,
‘TextData, Duration’

EXEC AddFilter
@TraceID,
‘Duration’,
15000,
‘>=’

EXEC StartTrace @TraceID
GO

Once you are done, you could  stop the trace by calling the following stored procedures. Important Note:  You can only view the trace file, after successfully stopping the trace and clearing it from memory: (Lets assume that the ID of the trace created above was 1)
 EXEC StopTrace 1
EXEC ClearTrace 1

Scenario 2: Get a list of  all the stored procedures called within a specific database:

In this scenario, I will show you, how to get a list of all the stored procedures called, from within a specific database. In this example, we will look for all stored procedure calls from msdb database. We will also capture the start time, end time, application name, client host name, NT user name and the domain name.
DECLARE @TraceID int, @DB_ID int

EXEC CreateTrace
‘C:My SQL TracesProceduresCalledInMSDB’,
@OutputTraceID = @TraceID OUT

EXEC AddEvent
@TraceID,
‘SP:Completed’,
‘TextData, StartTime, EndTime, ApplicationName, ClientHostName, NTUserName, NTDomainName, DatabaseID’

SET @DB_ID = DB_ID(‘msdb’)

EXEC AddFilter
@TraceID,
‘DatabaseID’,
@DB_ID

EXEC StartTrace @TraceID
GO

Scenario 3: Tracing for specific errors:

Let us imagine a scenario, where you deployed  a brand new application and database. Now the old database is not needed  anymore. So, you took the old database offline, but you want to make sure  no user or application is trying to access the old database. As you  probably know, when somebody or some application tries to open an offline  database, you get the following error: 942: Database ‘OldDatabase’ cannot be opened because it is offline. In the following example, we will setup a
trace that looks for error 942 and captures the time of the request, application name, NT user name and the client machine name from which the request originated. We will also specify that if the trace file already exists, it’ll be overwritten.


DECLARE @TraceID int

EXEC CreateTrace
‘C:Trapping942s’,
@OverwriteFile = 1,
@OutputTraceID = @TraceID OUTPUT

EXEC AddEvent
@TraceID,
‘Exception’,
‘Error, StartTime, ApplicationName, NTUserName, ClientHostName’

EXEC AddFilter
@TraceID,
‘Error’,
942

EXEC StartTrace @TraceID

Scenario 4: Troubleshooting
deadlocks:

In this scenario, I will show you how to setup a
trace to identify the connections (SPIDs) involved in a deadlock, using
the Deadlock and Deadlock Chain events.


DECLARE @TraceID int

EXEC dbo.CreateTrace
‘C:My SQL TracesDead Locks’,
@OutputTraceID = @TraceID OUT

EXEC dbo.AddEvent
@TraceID,
‘Lock:Deadlock, Lock:Deadlock Chain, RPC:Starting, SQL:BatchStarting’,
‘TextData’

EXEC dbo.StartTrace
@TraceID

Scenario 5: Identifying
stored procedure recompilations:

Stored procedure recompiles
have a potential to hinder the performance of your application. So it is
important to identify those procedures that are recompiling repeatedly,
and fix them, if the recompilation is not beneficial. The following
template creates a trace that logs the stored procedures that are
recompiling along with the database ID in which they are running. It also
captures EventSubClass. From SQL Server 2000 SP3 and above, EventSubClass
tells you the exact reason for the stored procedure recompilation. For
more information search Microsoft Knowledge Base (KB) for article
308737.


DECLARE @TraceID int

EXEC dbo.CreateTrace
‘C:My SQL TracesRecompilations’,
@OutputTraceID = @TraceID OUT

EXEC dbo.AddEvent
@TraceID,
‘SP:Recompile’,
‘ObjectID, ObjectName, EventSubClass, DatabaseID’

EXEC dbo.StartTrace
@TraceID

Scenario 6: Starting a
Blackbox trace:

A black box trace stores a record of the last 5 MB of trace information produced by the server. This is very useful for  troubleshooting nasty problems, bugs and access violation errors, that cause the SQL Server to shutdown. Consult SQL Server 2000 Books Online and  Microsoft Knowledge Base for more information on Blackbox traces.

DECLARE @TraceID int

EXEC CreateTrace
@Blackbox = 1,
@OutputTraceID = @TraceID OUT

EXEC StartTrace
@TraceID

Conclusion:

The
above scenarios, will just get you started, but you can really use these
stored procedures to setup complicated traces with various columns, events
and different types of filters. I hope you find my work useful. For the
sake of completeness, I’ll mention the fact that, you could even schedule
the above stored procedures, as SQL Agent jobs, in order to start the
traces at a desired date and time.

In the process of learning the
SQL Trace system stored procedures, I did stumble upon few bugs. For
example, when you set a filter on ObjectID, and then query the trace
definition using fn_trace_getfilterinfo function, the ObjectID reported
will be incorrect when the ObjectID is greater than 255 (SELECT value FROM
::fn_trace_getfilterinfo(@TraceID)).

One thing I observed with
Profiler is that, though the trace system stored procedures support the
comparison operators > and <, Profiler only shows >= and
<=.

Before we end, here are the links to some of the best SQL
Server performance tuning related books. I personally, read some of these
books and found them extremely useful and enlightening. Hope you find them
useful too:

Top

Book
Title
Review
available?
The SQL Server 2000 Performance Optimization and Tuning HandbookThe SQL Server
2000 Performance Optimization and Tuning Handbook
No
Microsoft SQL Server 2000 Performance Tuning Technical ReferenceMicrosoft SQL
Server 2000 Performance Tuning Technical Reference
Yes. Click here to
read
SQL Performance TuningSQL Performance
Tuning
No
The Guru's Guide to SQL Server Architecture and InternalsThe Guru’s Guide
to SQL Server Architecture and Internals
No
Inside Microsoft SQL Server 2000Inside Microsoft
SQL Server 2000
Yes. Click here to
read
Microsoft SQL Server 2000 Resource KitMicrosoft SQL
Server 2000 Resource Kit
Yes. Click here to
read

 

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s