Server-Side Traces in SQL Server: No Voodoo Required

Tim Ford profiler, server side traces, SQL 2 Comments Mar 21, 2012

Tracing without SQL Profiler

As a SQL Server DBA you’ll eventually find yourself trying to troubleshoot a performance issue that leads to you needing to capture the activity occurring on the SQL server itself. For many of us that means launching SQL Profiler and creating a trace to run against the server. When dealing with a server that is probably already under stress (since we tend not to give a darn about checking on SQL servers running just fine) you may not realize that relying on SQL Profiler may not give you a complete picture of the activity on your server.

SQL Profiler is just like any other client application – when running on a server under stress it may experience periods where its connection is getting dropped; no connection – no trace data. No trace data – no value to running the trace.

How do you get around this? You use server-side tracing.

Server Side Tracing: It’s Less Derivative than Using Profiler

SQL Profiler has to make a hop across the network from the server being traced to your workstation. There is a lot of room for failure there isn’t there? What if you were able to set up the trace completely within T/SQL running directly against the SQL instance and storing the results on the server itself? That’s exactly what server-side tracing is. It’s not running SQL Profiler on the SQL Server as you may have thought.

Do you want to get more SQL Server training with a side of fun, networking, and rejuvenation? Then join Tim Ford, Allen White, Kevin Kline, Brent Ozar, Kendra Little, and Jeremiah Peschka in Alaska this May for SQL Cruise Alaska 2012! All registrants received a 1 year license for Quest Software’s SQL Server tools – estimated value of $8000 – for free. See sqlcruise.com for details.

Microsoft provides a suite of extended store procedures that will allow you to build the trace, set the events, build the columns to return results for, and set filters all without firing up SQL Profiler. In fact, these are the commands the GUI build behind it’s 1998-style facade to run against the server.

Setting Up a Simple Trace

In the example I’m going to provide you here I’ll set up a trace that will monitor the activity against the Honey_Badger database. The process by which you create a server side trace follows this process flow each time:

Create the trace via sp_trace_create (parameters include the trace_id, trace file name, maximum file size, and stop time. Kalen Delaney highlights one more as well here.)
Set the events to collect data for by using sp_trace_setevent (parameters for this extended stored procedure you’ll be using are trace_id, event_id, column_id, and a parameter that signifies that the event is actively being traced.)
Set the filters for dialing-in the amount of data to return to the trace file through the use of sp_trace_setfilter. (Parameters you’ll need to deal with are, suprise, trace_id, column_id, logical operator, comparison operator, and value.)
Start the trace. You will do this via execution of sp_trace_setstatus by passing in the trace_id and the status value of 1.

There are a great number of values for each of the parameters in each one of the stored procedures listed above. Books Online did a very good job of presenting those in the links I provided. I’m not here to regurgitate good information; rather give my spin and fill in the holes missing in the documentation that is already out there. When doing the research on this topic I was shocked at the lack of information on the subject even though so many of us mention, tout, and recommend the use of server side traces. Please view the BOL links when crafting your own traces. What information seemed to be lacking? A good example with documented code. Going forward I hope to solve that problem for you Internetz! I’m going to be interested in returning trace information for the following events:

Logins
Logoffs
Existing Connections
Statement Completed

for the Honey_Badger database only. I also want to exclude any traffic that is generated through the use of the trace events themselves. That means that we will need to set up the trace, collect data (TextData, NTUserName, HostName, ApplicationName, LoginName, spid/session_id, Duration, Start/End times, Reads, Writes, CPU, and finally DatabaseName for each of the four event types mentioned above.) I then go on to set up two filters (one for the database name and another for the omission of any Profiler-generated traffic) and finally kick off the trace.

I should add that there are limitation to the display in my selected format for my blog. Copy and paste this code into SSMS and it’s far more gorgeous. Well, as gorgeous as t/sql can get…

-- Variable Declaration
 
DECLARE @return_code INT
DECLARE @trace_id INT
DECLARE @max_file_size bigint
DECLARE @file_name NVARCHAR(128)
DECLARE @event_is_on bit
DECLARE @stop_time datetime
 
-- Variable Values
SELECT @max_file_size = 5 --5 mb
SELECT @file_name = N'C:\Honey_Badger_Trace_' + cast(datepart(dd,getdate()) as varchar(3));
SELECT @event_is_on = 1
SELECT @stop_time = DATEADD(n,10,getdate()) --Run for 10 minutes
 
-- Trace Creation
EXEC @return_code = sp_trace_create @traceid = @trace_id output,
@options = 0,
@tracefile = @file_name,
@maxfilesize = @max_file_size,
@stoptime = @stop_time
 
-- Set Events and Data for Collection
--Audit Login
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 1, @on = @event_is_on; --TextData
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 6, @on = @event_is_on; --NTUserName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 8, @on = @event_is_on; --HostName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 10, @on = @event_is_on; 
 
--ApplicationName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 11, @on = @event_is_on; --LoginName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 12, @on = @event_is_on; --SPID
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 13, @on = @event_is_on; --Duration
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 14, @on = @event_is_on; --StartTime
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 15, @on = @event_is_on; --EndTime
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 16, @on = @event_is_on; --Reads (logical)
 
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 17, @on = @event_is_on; --Writes (physical)
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 18, @on = @event_is_on; --CPU
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 18, @on = @event_is_on; --DatabaseName
 
--Audit Logoff
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 1, @on = @event_is_on; --TextData
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 6, @on = @event_is_on; --NTUserName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 8, @on = @event_is_on; --HostName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 10, @on = @event_is_on; 
 
--ApplicationName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 11, @on = @event_is_on; --LoginName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 12, @on = @event_is_on; --SPID
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 13, @on = @event_is_on; --Duration
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 14, @on = @event_is_on; --StartTime
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 15, @on = @event_is_on; --EndTime
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 16, @on = @event_is_on; --Reads (logical)
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 17, @on = @event_is_on; --Writes (physical)
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 18, @on = @event_is_on; --CPU
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 18, @on = @event_is_on; --DatabaseName
 
--Existing Connections
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 1, @on = @event_is_on; --TextData
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 6, @on = @event_is_on; --NTUserName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 8, @on = @event_is_on; --HostName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 10, @on = @event_is_on; 
 
--ApplicationName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 11, @on = @event_is_on; --LoginName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 12, @on = @event_is_on; --SPID
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 13, @on = @event_is_on; --Duration
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 17, @on = @event_is_on; --StartTime
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 15, @on = @event_is_on; --EndTime
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 16, @on = @event_is_on; --Reads (logical)
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 17, @on = @event_is_on; --Writes (physical)
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 18, @on = @event_is_on; --CPU
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 18, @on = @event_is_on; --DatabaseName
 
--Statement Completed
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 1, @on = @event_is_on; --TextData
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 6, @on = @event_is_on; --NTUserName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 8, @on = @event_is_on; --HostName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 10, @on = @event_is_on; 
 
--ApplicationName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 11, @on = @event_is_on; --LoginName
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 12, @on = @event_is_on; --SPID
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 13, @on = @event_is_on; --Duration
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 41, @on = @event_is_on; --StartTime
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 15, @on = @event_is_on; --EndTime
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 16, @on = @event_is_on; --Reads (logical)
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 17, @on = @event_is_on; --Writes (physical)
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 18, @on = @event_is_on; --CPU
EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 18, @on = @event_is_on; --DatabaseName
 
-- Set The Trace Filters
-- Include Database = Honey_Badger
EXEC sp_trace_setfilter
@traceid = @trace_id,
@columnid = 35, -- Database Name column
@logical_operator = 0, -- (0 = AND, 1 = OR)
@comparison_operator = 0, -- Equals
@value = N'Honey_Badger' --DatabaseName = 'Honey_Badger'
 
-- Exclude SQL Profiler Activity from the Trace
EXEC sp_trace_setfilter
@traceid = @trace_id,
@columnid = 10, -- Application Name column
@logical_operator = 0, -- (0 = AND, 1 = OR)
@comparison_operator = 7, -- NOT LIKE
@value = N'SQL Profiler'
 
-- Start the trace
EXEC sp_trace_setstatus @trace_id, 1; --(1 = ON, 0 = OFF, 2 = Delete)
 
-- Just so you know... the trace_id is...
SELECT TraceID = @trace_id;

-- Variable Declaration DECLARE @return_code INT DECLARE @trace_id INT DECLARE @max_file_size bigint DECLARE @file_name NVARCHAR(128) DECLARE @event_is_on bit DECLARE @stop_time datetime -- Variable Values SELECT @max_file_size = 5 --5 mb SELECT @file_name = N'C:\Honey_Badger_Trace_' + cast(datepart(dd,getdate()) as varchar(3)); SELECT @event_is_on = 1 SELECT @stop_time = DATEADD(n,10,getdate()) --Run for 10 minutes -- Trace Creation EXEC @return_code = sp_trace_create @traceid = @trace_id output, @options = 0, @tracefile = @file_name, @maxfilesize = @max_file_size, @stoptime = @stop_time -- Set Events and Data for Collection --Audit Login EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 1, @on = @event_is_on; --TextData EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 6, @on = @event_is_on; --NTUserName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 8, @on = @event_is_on; --HostName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 10, @on = @event_is_on; --ApplicationName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 11, @on = @event_is_on; --LoginName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 12, @on = @event_is_on; --SPID EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 13, @on = @event_is_on; --Duration EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 14, @on = @event_is_on; --StartTime EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 15, @on = @event_is_on; --EndTime EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 16, @on = @event_is_on; --Reads (logical) EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 17, @on = @event_is_on; --Writes (physical) EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 18, @on = @event_is_on; --CPU EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 14, @columnid = 18, @on = @event_is_on; --DatabaseName --Audit Logoff EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 1, @on = @event_is_on; --TextData EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 6, @on = @event_is_on; --NTUserName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 8, @on = @event_is_on; --HostName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 10, @on = @event_is_on; --ApplicationName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 11, @on = @event_is_on; --LoginName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 12, @on = @event_is_on; --SPID EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 13, @on = @event_is_on; --Duration EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 14, @on = @event_is_on; --StartTime EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 15, @on = @event_is_on; --EndTime EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 16, @on = @event_is_on; --Reads (logical) EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 17, @on = @event_is_on; --Writes (physical) EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 18, @on = @event_is_on; --CPU EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 15, @columnid = 18, @on = @event_is_on; --DatabaseName --Existing Connections EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 1, @on = @event_is_on; --TextData EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 6, @on = @event_is_on; --NTUserName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 8, @on = @event_is_on; --HostName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 10, @on = @event_is_on; --ApplicationName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 11, @on = @event_is_on; --LoginName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 12, @on = @event_is_on; --SPID EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 13, @on = @event_is_on; --Duration EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 17, @on = @event_is_on; --StartTime EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 15, @on = @event_is_on; --EndTime EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 16, @on = @event_is_on; --Reads (logical) EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 17, @on = @event_is_on; --Writes (physical) EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 18, @on = @event_is_on; --CPU EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 17, @columnid = 18, @on = @event_is_on; --DatabaseName --Statement Completed EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 1, @on = @event_is_on; --TextData EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 6, @on = @event_is_on; --NTUserName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 8, @on = @event_is_on; --HostName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 10, @on = @event_is_on; --ApplicationName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 11, @on = @event_is_on; --LoginName EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 12, @on = @event_is_on; --SPID EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 13, @on = @event_is_on; --Duration EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 41, @on = @event_is_on; --StartTime EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 15, @on = @event_is_on; --EndTime EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 16, @on = @event_is_on; --Reads (logical) EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 17, @on = @event_is_on; --Writes (physical) EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 18, @on = @event_is_on; --CPU EXEC sp_trace_setevent @traceid= @trace_id, @eventid = 41, @columnid = 18, @on = @event_is_on; --DatabaseName -- Set The Trace Filters -- Include Database = Honey_Badger EXEC sp_trace_setfilter @traceid = @trace_id, @columnid = 35, -- Database Name column @logical_operator = 0, -- (0 = AND, 1 = OR) @comparison_operator = 0, -- Equals @value = N'Honey_Badger' --DatabaseName = 'Honey_Badger' -- Exclude SQL Profiler Activity from the Trace EXEC sp_trace_setfilter @traceid = @trace_id, @columnid = 10, -- Application Name column @logical_operator = 0, -- (0 = AND, 1 = OR) @comparison_operator = 7, -- NOT LIKE @value = N'SQL Profiler' -- Start the trace EXEC sp_trace_setstatus @trace_id, 1; --(1 = ON, 0 = OFF, 2 = Delete) -- Just so you know... the trace_id is... SELECT TraceID = @trace_id;

Then I’ll run some code against the Honey_Badger database to generate some trace data:

USE Honey_Badger;
GO
 
CREATE TABLE Foo (id int);
 
INSERT INTO Foo (id)
VALUES (1);
 
SELECT * FROM Foo;
 
DROP TABLE Foo;

If we look at the sys.traces table while the trace is running (you have 10 minutes to do it.) You’ll see the trace is running:

Record 2 will go away once the trace hits that magic stop_time (which it has by the time you read this.)

All that is left is the task of opening SQL Profiler and loading the trace file that was generated:

What? You’re Still Here?

Hopefully this gives you a little more insight into server side traces. If not, I’ve successfully made it look like you were reading something work-related while your manager shuffled through making sure that work was getting done. You’re welcome either way.