Server-Side Tracing and Collection

Behind its nice user interface, SQL Server Profiler is nothing more than a fairly lightweight wrapper over a handful of system stored procedures which expose the true functionality of SQL Trace. In this section, we will explore which stored procedures are used, and how to harness SQL Server Profiler as a scripting tool rather than a tracing interface.

The following system stored procedures are used to define and manage traces:

• sp_trace_create is used to define a trace and specify an output file location as well as other options that I’ll cover in the coming pages. This stored procedure returns a handle to the created trace, in the form of an integer trace ID.
• sp_trace_setevent is used to add event/column combinations to traces based on the trace ID, as well as to remove them, if necessary, from traces in which they have already been defined.
• sp_trace_setfilter is used to define event filters based on trace columns.
• sp_trace_setstatus is called to turn on a trace, to stop a trace, and to delete a trace definition once you’re done with it. Traces can be started and stopped multiple times over their lifespan.

Scripting Server-Side Traces

Rather than delve directly into the syntax specifications for each of the stored procedures—all of which are documented in detail in SQL Server Books Online—it is a bit more interesting to observe them in action. To begin, open up SQL Server Profiler, start a new trace with the default template, and unselect all events except for SQL:BatchCompleted, as shown in Figure 2-11.

Figure 2-11 Trace events with only SQL:BatchCompleted selected

Next, remove the default filter on the ApplicationName column (set to not pick up SQL Server Profiler events), and add a filter on Duration, for greater than or equal to 10 milliseconds, as shown in Figure 2-12.

Figure 2-12 Filter on Duration set to greater than or equal to 10 milliseconds

Once you’re finished, click Run to start the trace, then immediately click the Stop button. Because of the workflow required by the SQL Server Profiler user interface, you must actually start a trace before you can script it. On the File menu, select Export, then Script Trace Definition, then For SQL Server 2005. This will produce a script similar to the following (note, we’ve edited SQL Server Profiler’s output a bit for brevity and readability):

declare @rc int 
declare @TraceID int 
declare @maxfilesize bigint 
set @maxfilesize = 5
exec @rc = sp_trace_create
@TraceID output, 
0, 
N'InsertFileNameHere', 
@maxfilesize, 
NULL
if (@rc != 0) goto finish 
-- Set the events 
declare @on bit 
set @on = 1 
exec sp_trace_setevent @TraceID, 12, 15, @on 
exec sp_trace_setevent @TraceID, 12, 16, @on 
exec sp_trace_setevent @TraceID, 12, 1, @on 
exec sp_trace_setevent @TraceID, 12, 9, @on 
exec sp_trace_setevent @TraceID, 12, 17, @on 
exec sp_trace_setevent @TraceID, 12, 6, @on 
exec sp_trace_setevent @TraceID, 12, 10, @on 
exec sp_trace_setevent @TraceID, 12, 14, @on 
exec sp_trace_setevent @TraceID, 12, 18, @on 
exec sp_trace_setevent @TraceID, 12, 11, @on 
exec sp_trace_setevent @TraceID, 12, 12, @on 
exec sp_trace_setevent @TraceID, 12, 13, @on 
-- Set the Filters 
declare @bigintfilter bigint 
set @bigintfilter = 10000 
exec sp_trace_setfilter @TraceID, 13, 0, 4, @bigintfilter 
-- Set the trace status to start 
exec sp_trace_setstatus @TraceID, 1 
-- display trace id for future references 
select TraceID=@TraceID 
finish: 
go

Note An option also exists to script the trace definition for SQL Server 2000. The SQL Trace stored procedures did not change much between SQL Server 2000 and SQL Server 2005, but several new events and columns were added to the product. Scripting for SQL Server 2000 simply drops from the script any events that are not backward-compatible.

This script is an extremely simple yet complete definition of a trace that uses the file provider. A couple of placeholder values need to be modified, but for the most part this is totally functional as-is. Given the complexity of working directly with the SQL Trace stored procedures, we generally define a trace using SQL Server Profiler’s UI, then script it and work from there. This way you get the best of both worlds: ease of use combined with the efficiency of server-side traces using the file provider.

This script does a few different things, so we will walk through each stage:

1. First, the script defines a few variables to be used in the process. The @rc variable will be used to get a return code from sp_trace_create. The @TraceID variable will hold the handle to the newly created trace. Finally, the @maxfilesize variable defines the maximum size (in MB) per trace file. When running server-side traces, the file provider can be configured to automatically create rollover files as the primary trace file fills up. This can be useful if you’re working on a drive with limited space, as you can move previously filled files off to another device. In addition, smaller files can make it easier to manipulate subsets of the collected data. Finally, rollover files also have their utility in high-load scenarios, as will be discussed later in this chapter. However, most of the time these are not necessary, and a value of 5 is a bit small for the majority of scenarios. We’ll further discuss this value, as well as uses for rollover files, in the “Tracing Considerations and Design” section.

2. Next, the script calls the sp_trace_create stored procedure, which initializes—but does not start—the trace. The parameters specified here are the output parameter for the trace ID of the newly created trace; 0 for the options parameter—meaning that rollover files should not be used; a placeholder for a server-side file path, which should be changed before using this script; the maximum file size as defined by the @maxfilesize variable; and NULL for the stop date—this trace will only stop when it is told to. Note that there is also a final parameter into sp_trace_create, which allows the user to set the maximum number of rollover files. This parameter, called @filecount in the sp_trace_create documentation, is new in SQL Server 2005 and is not added automatically to the trace definition scripts created with the Script Trace Definition option. The @filecount parameter doesn’t apply here, since the options parameter was set to 0 and no rollover files will be created, but it can be useful in many other cases. Note that since rollover files are disabled, if the maximum file size is reached the trace will automatically be stopped and closed. Note The file extension .trc will automatically be appended to the file path specified for the output trace file. If you use the .trc extension in your file name, for example C:\mytrace.trc, the file on disk will be C:\mytrace.trc.trc.

3. Next, sp_trace_setevent is used to define the event/column combinations used for the trace. In this case, to keep things simple, only event 12—SQL:BatchCompleted—is used. One call to sp_trace_setevent is required for each event/column combination used in the trace. As an aside, note that the @on parameter must be a bit. Since numeric literals in SQL Server are implicitly cast as integers by default, the local @on variable is needed to force the value to be treated appropriately by the stored procedure.

4. Once events are set, filters are defined. In this case, column 13 (Duration) is filtered using the “and” logical operator (the third parameter, with a value of 0) and the “greater than or equal to” comparison operator (value of 4 in the fourth parameter). The actual value is passed in as the final parameter. Note that it is shown in the script in microseconds; SQL Trace uses microseconds for its durations, although the default standard of time in SQL Server Profiler is milliseconds. To change the SQL Server Profiler default, click Tools, then Options, and check the box for Show values in Duration column in microseconds (SQL Server 2005 only). Note SQL Trace offers both “and” and “or” logical operators that can be combined if multiple filters are used. However, there is no way to indicate parentheses or other grouping constructs, meaning that the order of operations is limited to left-to-right evaluation. This means that an expression such as A and B or C and D is logically evaluated by SQL Trace as (((A and B) or C) and D). However, SQL Trace will internally break the filters into groups based on columns being filtered. So the expression Column1=10 or Column1=20 and Column3=15 or Column3=25 will actually be evaluated as (Column1=10 or Column1=20) and (Column3=15 or Column3=25). Not only is this somewhat confusing, but it can make certain conditions difficult or impossible to express. Keep in mind that in some cases you may have to break up your filter criteria and create multiple traces in order to capture everything the way you intend to intended.

5. The trace has now been created, event and column combinations set, and filters defined. The final thing to do is actually start tracing. This is done via the call to sp_trace_setstatus, with a value of 1 for the second parameter.

Querying Server-Side Trace Metadata

After modifying the file name placeholder appropriately and running the test script on my server, I got back a value of 2 for the trace ID. Using a trace ID you can retrieve a variety of metadata about the trace from the sys.traces catalog view, such as is done by the following query:

SELECT
    status, 
    path, 
    max_size, 
    buffer_count, 
    buffer_size, 
    event_count, 
    dropped_event_count 
FROM sys.traces 
WHERE id = 2

This query returns the trace status, which will be 1 (started) or 0 (stopped); the server-side path to the trace file (or NULL if the trace is using the rowset provider); the maximum file size (or again, NULL in the case of the rowset provider); information about how many buffers of what size are in use for processing the I/O; the number of events captured; and the number of dropped events (in this case, NULL if your trace is using the file provider).

Note For readers migrating from SQL Server 2000, note that the sys.traces view replaces the older fn_trace_getinfo function. This older function returns only a small subset of the data returned by the sys.traces view, so it’s definitely better to use the view going forward.

In addition to the sys.traces catalog view, SQL Server ships with a few other views and functions to help derive other information about traces running on the server.

fn_trace_geteventinfo

This function returns the numeric combinations of events and columns selected for the trace, in a tabular format. The following Transact-SQL returns this data for trace ID 2:

SELECT *
FROM fn_trace_geteventinfo(2)

The output from running this query on the trace created in the preceding script is shown in Table 2-1.

Table 2-1 Selected Trace Events and Columns as Returned by fn_trace_geteveninfo for a Specific Trace

sys.trace_events and sys.trace_columns

The numeric representations of trace events and columns are not especially interesting on their own. In order to be able to properly query this data a textual representation is necessary.

The sys.trace_events and sys.trace_columns contain not only text describing the events and columns respectively, but also other information such as data types for the columns and whether they are filterable. Combining these views with the above query against the fn_trace_ geteventinfo function, we can get a much easier to read version of the same output:

SELECT 
    e.name AS Event_Name, 
    c.name AS Column_Name
FROM fn_trace_geteventinfo(2) ei
JOIN sys.trace_events e ON ei.eventid = e.trace_event_id 
JOIN sys.trace_columns c ON ei.columnid = c.trace_column_id

The output from this query is shown in Table 2-2.

Table 2-2 Selected Trace Events and Columns as Rendered To Test for a Specific Trace

fn_trace_getfilterinfo

To get information about which filter values were set for a trace, the fn_trace_getfilterinfo function can be used. This function returns the column ID being filtered (which can be joined to the sys.trace_columns view for more information), the logical operator, comparison operator, and the value of the filter. Following is an example of its use:

SELECT 
    columnid, 
    logical_operator, 
    comparison_operator, 
    value 
FROM fn_trace_getfilterinfo(2)

Retrieving Data from Server-Side Traces

Once a trace is started, the obvious next move is to actually read the collected data. This is done using the fn_trace_gettable function. This function takes two parameters: The name of the first file from which to read the data, and the maximum number of rollover files to read from (should any exist). The following Transact-SQL code reads the trace file located at C:\inside_sql.trc:

SELECT *
FROM fn_trace_gettable('c:\inside_sql.trc', 1)

A trace file can be read at any time, even while a trace is actively writing data to it. Note that this is probably not a great idea in most scenarios, as it will increase disk contention, thereby decreasing the speed with which events can be written to the table and increasing the possibility of blocking. However, in situations in which you’re collecting data infrequently—such as when you’ve filtered for a very specific stored procedure pattern that isn’t called often—this is an easy way to find out what you’ve collected so far.

Because fn_trace_gettable is a table-valued function, its uses within Transact-SQL are virtually limitless. It can be used as-is to formulate queries, or inserted into a table so that indexes can be created. In the latter case, it’s probably a good idea to use SELECT INTO, in order to take advantage of minimal logging:

SELECT *
INTO inside_sql_trace
FROM fn_trace_gettable('c:\inside_sql.trc', 1)

Once the data has been loaded into a table, it can be sliced and diced any number of ways in order to troubleshoot or answer questions. I’ll describe several such queries in the “Troubleshooting and Analysis with Traces” section later in this chapter.

Stopping and Closing Traces

When a trace is first created, it has the status of 0, stopped (or not yet started, in that case). A trace can be brought back to that state at any time, using sp_trace_setstatus. To set trace ID 2 to a status of stopped, the following Transact-SQL code is used:

EXEC sp_trace_setstatus 2, 0

Aside from the obvious benefit of the trace no longer collecting data, there is another perk to doing this: Once the trace is in a stopped state, you can modify the event/column selections and filters using the appropriate stored procedures, without re-creating the trace. This can be extremely useful if you only need to make a minor adjustment.

If you are actually finished tracing and do not wish to continue at a later time, you can remove the trace definition from the system altogether by setting its status to 2:

EXEC sp_trace_setstatus 2, 2

Note Trace definitions will be automatically removed in the case of a SQL Server service restart, so if you do need to run the same trace again later either save it as a Profiler template or save the script used to start it.

Investigating the Rowset Provider

Most of this section has dealt with how to work with the file provider using server-side traces, but some readers are undoubtedly asking themselves how SQL Server Profiler interfaces with the rowset provider. The rowset provider and its interfaces are completely undocumented. However, because SQL Server Profiler is doing nothing more than calling stored procedures under the covers, it is not too difficult to find out what’s going on. As a matter of fact, you can use a somewhat recursive process: use SQL Server Profiler to trace activity generated by itself.

A given trace session will not be able to capture all of its own events (the trace won’t be running yet when some of them occur), so to see how Profiler works we need to set up two traces: an initial trace configured to watch for SQL Server Profiler activity, and a second trace to produce the activity for the first trace to capture. To begin with, open SQL Server Profiler and create a new trace using the default template. In the Edit Filter dialog box, remove the default Not Like filter on ApplicationName, and replace it with a Like filter on ApplicationName for the string SQL Server Profiler%. This filter will capture all activity that is produced by any SQL Server Profiler session.

Start that trace, then load up another trace using the default template and start it. The first trace window will now fill with calls to the various sp_trace stored procedures, fired via RPC:Completed events. The first hint that something different happens when using the rowset provider is the call made to sp_trace_create:

declare @p1 int 
exec sp_trace_create @p1 output,1,NULL,NULL,NULL 
select @p1

The second parameter, used for options, is set to 1, a value not documented in SQL Server Books Online. This is the value that turns on the rowset provider. And the remainder of the parameters, which deal with file output, are populated with NULLs.

Note The *sp_trace_create @options* parameter is actually a bitmask—multiple options can be set simultaneously. To do that, simply add up the values for each of the options you’d like. With only three documented values and one undocumented value there aren’t a whole lot of possible combinations, but it’s still something to keep in mind.

Much of the rest of the captured activity will look familiar at this point; you’ll see normal-looking calls to sp_trace_setevent, sp_trace_setfilter, and sp_trace_setstatus. However, to see the complete picture you’ll have to stop the second trace (the one actually generating the trace activity being captured). As soon as the second trace stops, the first trace will capture the following RPC:Completed event:

exec sp_executesql N'exec sp_trace_getdata @P1, 0',N'@P1 int',3

In this case, 3 is the trace ID for the second trace on our system. Given this set of input parameters, the sp_trace_getdata stored procedure streams event data back to the caller in a tabular format, and does not return until the trace is stopped. The second parameter is undocumented and doesn’t need to be set.

Unfortunately, the tabular format produced by sp_trace_getdata is far from recognizable, and is not in the standard trace table format. By modifying the previous file-based trace, we can produce a rowset-based trace using the following Transact-SQL:

declare @rc int 
declare @TraceID int
exec @rc = sp_trace_create
@TraceID output, 
1, 
NULL, 
NULL, 
NULL
if (@rc != 0) goto finish 
-- Set the events 
declare @on bit set @on = 1 
exec sp_trace_setevent @TraceID, 12, 15, @on 
exec sp_trace_setevent @TraceID, 12, 16, @on 
exec sp_trace_setevent @TraceID, 12, 1, @on 
exec sp_trace_setevent @TraceID, 12, 9, @on 
exec sp_trace_setevent @TraceID, 12, 17, @on 
exec sp_trace_setevent @TraceID, 12, 6, @on 
exec sp_trace_setevent @TraceID, 12, 10, @on 
exec sp_trace_setevent @TraceID, 12, 14, @on 
exec sp_trace_setevent @TraceID, 12, 18, @on 
exec sp_trace_setevent @TraceID, 12, 11, @on 
exec sp_trace_setevent @TraceID, 12, 12, @on 
exec sp_trace_setevent @TraceID, 12, 13, @on 
-- Set the Filters 
declare @bigintfilter bigint 
set @bigintfilter = 10000 
exec sp_trace_setfilter @TraceID, 13, 0, 4, @bigintfilter 
-- Set the trace status to start 
exec sp_trace_setstatus @TraceID, 1 
-- display trace id for future references 
select TraceID=@TraceID 
exec sp_executesql
N'exec sp_trace_getdata @P1, 0', 
N'@P1 int', 
@TraceID 
finish: 
go

Running this code, then issuing a WAITFOR DELAY '00:00:10' in another window, produces the output (truncated and edited for brevity), as shown in Table 2-3.

Table 2-3 Output from the Rowset Provider as Exposed via sp_trace_getdata for our trace

Each of the values in the columnid column corresponds to a trace data column ID. The length and data columns are relatively self-explanatory—data is a binary-encoded value that corresponds to the collected column, and length is the number of bytes used by the data column. Each row of the output coincides with one column of one event. SQL Server Profiler pulls these events from the rowset provider via a call to sp_trace_getdata and performs a “pivot” to produce the human-readable output we’re used to seeing. This is yet another reason that the rowset provider can be less efficient than the file provider—sending so many rows can produce a huge amount of network traffic.

If you do require rowset provider-like behavior for your monitoring needs, you luckily will not need to figure out how to manipulate this data. SQL Server 2005 ships with a series of managed classes in the Microsoft.SqlServer.Management.Trace namespace, designed to help with setting up and consuming rowset traces. The use of these classes is beyond the scope of this chapter, but they are well documented in the SQL Server TechCenter on TechNet, and readers should have no trouble figuring out how to exploit what they offer.

Now that we’ve explored some of the ins and outs of SQL Trace and SQL Server Profiler, the next section will take things to a slightly more practical level, showing you how you can apply SQL Trace to a variety of real-world problems.

< Back      Next >

© Microsoft. All Rights Reserved.