Automating Server-Side Tracing in SQL Server

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. Bu t 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:

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

Stored procedure name Parameter usage
CreateTraceCreates an empty trace
definition, ready for use.
@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.

AddEventAdds
events and columns to the trace definition.

 

@TraceID– intThe 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

AddFilterAdds filters to existing trace
definitions

Click here to download

@TraceID– intThe 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.

StartTraceStarts a specified
trace.
@TraceID– intThe ID of the trace (created by CreateTrace), to be started.

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

StopTraceStops a specified
trace.
@TraceID– intThe ID of the trace (created by CreateTrace), to be stopped.

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

ClearTraceClears the definition of the
trace from memory.
@TraceID– intThe 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 <=.

 

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