Trace That Event with SQL Server Profiler

Tracing client requests and server responses isn't easy if you're using SQL Server versions before 6.5. A freeware tracing tool called SQLEye, a network Open Data Services (ODS) sniffer, can do the job, but it's hard to set up and complex to use, even for basic traces.

SQL Server 6.5 introduced a graphical tool called SQL Trace, which makes SQLEye easier to use. SQL Trace, which can save its output to a trace file or an SQL script file, can track a limited number of events and filters and tell you, for example, which SQL statements a client sent and which stored procedures the server executed. But if you need to know what's happening inside the server, such as which stored procedures were called by other stored procedures or when a connection acquired or released a lock, you're out of luck—unless you have SQL Server 7.0.

SQL Server 7.0's powerful tracing functions and new tracing tool, SQL Profiler, enhance SQL Trace's functionality and introduce new capabilities for monitoring, analyzing, and tuning SQL Server. Profiler captures detailed information about server events, taking you behind the scenes to help you discover which queries led to a deadlock, what's causing slow-running queries, what activities occurred inside a stored procedure, and more. Not only can you determine whether a certain event occurred, but you can analyze the activities that led to the event. Besides intercepting client requests and server responses, Profiler captures events that internal server components generate.

Setting up a simple Profiler trace is straightforward, but you can quickly get lost in the vast data such a trace generates. Profiler solves this problem by providing filters that let you control how much and what kind of data the trace includes. This article gets you started with SQL Profiler, showing you how to graphically define a trace. And the sidebar "SQL Server's Black Box" covers SQL Server 7.0's Flight Recorder function, which traces the last 100 queries. I delve deeper into Profiler's and SQL Server 7.0's tracing capabilities in "Problem-Solving with SQL Profiler." And don't miss "Boost Performance with the Index Tuning Wizard" to see how another SQL Server 7.0 tool, the Index Tuning Wizard, can help you optimize query performance.

Firm Foundation

Figure 1 shows SQL Server 7.0's trace architecture, consisting of event producers, event queues, and event consumers.

Event producers—such as ODS, the query processor, and the storage engine—generate events. Note that the query processor and the storage engine are internal server components. ODS, which passes client requests to the server and server responses back to the client, receives remote stored procedure calls and batches and manages client/server connections. The query processor generates an execution plan for a query, choosing, for example, which indexes and join algorithms to use and whether to perform a scan or an index seek. The storage engine manages database files and their data pages and is responsible for object access, object creation, and so on. The storage engine has two managers: the Lock Manager, which handles transactions and locks, and the Log Manager, which handles logging and recovery. Errors and warnings generate events. In addition, you can generate your own user-defined events for SQL Server 7.0 to trace by using the extended stored procedure xp_trace_generate_event. For example, by using this procedure in a trigger, you could have SQL Profiler trace a user-defined event such as a customer deletion (you'll find more about the extended stored procedures for tracing in "Problem-Solving with SQL Profiler").

Event queues collect the events that producers generate and consumers extract. These queues, which internal server threads manage, filter the events based on criteria you set up, then route the events to event consumers.

Event consumers asynchronously extract and process events from the queues. Potential consumers include SQL Profiler, operating system files, SQL Server tables, the Windows application event log (only with extended stored procedures), remote servers, and custom applications that read directly from the queues.

Graphically Defining a Trace

You can launch SQL Profiler from either the SQL Server 7.0 program group or the SQL Server Enterprise Manager's Tools menu. Profiler lets you trace server events based on a trace definition, or the definition of what events to capture, where to send the results, and what data to include. Profiler provides sample traces you can modify for your particular needs. To open and modify an existing trace definition, click the Edit Trace Properties icon or choose Open, Trace Definition from the File menu. ("Using SQL Profiler," July 1999, covers Profiler's sample traces.) Enterprise Manager also provides a Trace Wizard that lets you quickly set up traces to investigate a variety of problems, including deadlocks. (For more about the Trace Wizard, see "Problem-Solving with SQL Profiler.")

Instead of modifying an existing trace definition or using the Trace Wizard, let's walk through setting up a trace definition in Profiler from scratch. To start a new trace definition, click the New Trace icon or choose New, Trace from the File menu. The resulting Trace Properties dialog box has four tabs: Events, Data Columns, Filters, and General. By default, the Events tab shows 41 events, and the Data Columns tab shows 20 columns. To get a full list of events and columns, which includes 28 additional events and 5 additional data columns, you can choose Options from the Tools menu and select All event classes and All data columns, respectively. Note, however, that the Trace Properties dialog box is modal, meaning you can't perform any other actions in Profiler while this dialog box is open. If you want to see all events and columns, you must select those options in Profiler's Trace Options dialog box before defining your trace.

Events

The Events tab on the Trace Properties dialog box lets you choose which events to trace, as Screen 1 shows. The list of events might look overwhelming at first, especially if you chose to see all event classes. But as you gain experience with Profiler, you'll learn which events to trace to analyze specific kinds of situations. Note that if you start SQL Server with the ­x option, which disables gathering statistics for the performance monitor, you won't be able to trace events with Profiler either.

Profiler groups events into the following categories: Cursors, Error and Warning, Locks, Misc., Objects, Scans, Sessions, SQL Operators, Stored Procedures, Trans-actions, TSQL, and User Configurable. Some events you want to trace might overlap categories. For example, if you want to trace Transact SQL (T-SQL) statements, you might need to trace SQL:Batch-Starting, SQL:BatchCompleted, SQL:Stmt- Starting, SQL:StmtCompleted, SP:StmtStarting, SP:StmtCompleted, RPC:Starting, and RPC:Completed.

Some events provide more information than others. In the SQL Operators category, for example, the Select, Insert, Update, and Delete events simply show that a certain Data Manipulation Language (DML) operation occurred. In the Stored Procedures category, SP:Starting and SP:Completed indicate that a certain stored procedure started or completed. In addition, SP:StmtStarting and SP:StmtCompleted show the starting and completion of each statement inside a stored procedure. In the TSQL category, the events SQL:BatchStarting and SQL:BatchCompleted indicate the starting and completion of a batch, and the events SQL:StmtStarting and SQL:StmtCompleted indicate the starting and completion of a batch statement. The TSQL category also includes events that indicate the starting and completion of a remote stored procedure call.

The decision to trace a starting event or a completion event (or both) depends on the information you want. Usually, starting statements are helpful when you need to track the chronological execution of events, but they supply scant information: server process ID (SPID), connection ID, and start time. Completion events supply more information because after an event is completed, SQL Server can calculate CPU time used, duration (elapsed time), the number of logical reads and physical writes performed, and so on.

Data Columns

Screen 2 shows the Data Columns tab, where you select what performance information—such as CPU time, duration, logical reads, and physical writes—the trace provides. Data columns also report information about the environment that generated the trace, such as SPID, host name, database ID, transaction ID, and the text of a statement.

Not every data column is relevant for every event. Sometimes it's obvious that a certain data column is irrelevant for a particular event. For example, a starting event doesn't provide performance information. However, the SP:Completed event doesn't contain performance information either, whereas other completion events—such as SP:StmtCompleted, SQL:StmtCompleted, and SQL:BatchCompleted—do provide that information. Finding out which data columns are relevant for the events you want to capture is important because if you filter by certain trace event criteria, such as minimum CPU time, Profiler won't include events that don't supply this information.

Profiler's data columns feature a powerful organizational tool called groups. You can organize your view of events by one or more groups simply by moving the data columns you're interested in to the Groups section. You can apply this grouping before you start the trace or after you open the trace output file or table. While a trace is running, it makes more sense to see the added events in chronological order. But later, you can play with different groupings to get different views of the events. You'll also see the number of events that belong to each group along with the group's caption.

Filters

Profiler can produce an enormous amount of information. But if you gather it all, you might find it impossible to find the specific information you need. Filters let you trace only the events you think are important to monitor and analyze. And by applying the filters before you start the trace, you eliminate the performance penalty of tracing events you don't need.

Screen 3 shows the Filters tab. Profiler supplies three kinds of filters: specific-value filters, range filters, and inclusion/exclusion filters. By default, Profiler defines a filter that excludes all events it generates. But you can remove this filter if you need to see what Profiler is doing behind the scenes.

Specific-value filters let you supply a value to filter on for the following data columns: connection ID, database ID, object ID, and SPID. You can set only one value for each of these columns except object ID, which also lets you exclude system objects.

Range filters, which let you filter on a minimum and/or maximum numeric value, are available for CPU (milliseconds), duration (elapsed time in milliseconds), reads (logical), and writes (physical). You might use a range filter, for example, to trace only queries that have a certain minimum CPU time when you're trying to find long-running queries.

Inclusion/exclusion filters let you include or exclude only events that have a certain string in the data those events capture. You can use the percent sign (%) as a wildcard replacement for any number of unknown characters. If you want to specify more than one string, you can separate the strings with a semicolon (;). For example, to include only SQL user names that begin with the string hr_ or mgmt_, except the user hr_mark, you can use hr_%;mgmt_% as the inclusion filter and hr_mark as the exclusion filter. This kind of filter is available for application name, Windows NT or Windows 2000 (Win2K) user name, server name, SQL Server user name, and text.

What if you don't know exactly what to filter on or you want to play with a few filters separately on the same output after you stop the trace? In these cases, you can define the most inclusive filters before you start the trace, and after you stop the trace, you can open the output file or table and experiment with more exclusive filters. If you're tracing a deadlock situation, for example, after you find out which SPIDs participated in the deadlock, you can filter the trace once by one SPID, then open the trace file in another window for filtering by the other SPID.

General Options

Screen 4 shows the General tab, which lets you choose the trace destination, or where to send the trace results. Not all possible destinations are available from Profiler. For example, you can send trace output to the NT application log or forward it to a different server only by using a set of SQL Server 7.0 extended stored procedures for tracing. I cover this set in "Problem-Solving with SQL Server." However, the following destinations are available from Profiler:

Screen. If you're using Profiler to trace events (instead of using SQL Server 7.0's extended stored procedures), trace output will always go to the screen—whether you select another destination or not. You can, however, later save the output as an SQL script file, a trace file, or a table by choosing the Save As option from the File menu. Note that stopping and restarting the trace clears the previous output, so you need to save your results before restarting the trace. Also, if you change the trace properties without reopening a saved trace, the properties won't take effect until you stop and restart the trace. (You can read more about stopping and restarting traces in "Problem-Solving with SQL Profiler.")

File. If you send the output to a trace file, you can analyze it later. In addition, files let you look at the trace from different views. You might want to organize the output by different groups or data columns or even remove certain traced events and data columns. The advantage to sending the output to a trace file instead of a table is that it consumes less memory and is a lot faster because direct file system I/O doesn't incur the memory and CPU overhead that table inserts do. For instance, with a file, you don't have to spend resources handling concurrency or consistency problems.

Table. Using a table to analyze trace output can consume memory and CPU resources, but it gives you much more flexibility than a file. For example, you can use a Microsoft Excel PivotTable that uses the trace table as its data source and lets you dynamically drag the information to different areas of the PivotTable (page, rows, columns, data) to form a desired trace view. Tables also give you more flexible filtering criteria than Profiler. With Profiler, for instance, you can't analyze all events that have, say, SPIDs 8 or 9. But you can create such a filter by performing the following simple query:

SELECT * FROM mytracetable WHERE SPID in (8, 9)

You can also create triggers on a table to take certain actions as a result of system events—a function you can't perform otherwise because you can't create triggers on system tables.

You can let Profiler create the output table based on the selected data columns, or you can create a table that meets your specific objectives. For example, I created a table that enables triggers to check the TextData column. In Profiler-generated tables, this column is the ntext datatype, which is inaccessible to triggers. For my table, I simply changed the table structure to use the nvarchar (instead of ntext) datatype in the TextData column. Even if you decide to create a table, you can let Profiler create it first, then generate a script for its creation from Enterprise Manager (right-click the table name, choose All Tasks, then Generate SQL Script) and slightly change the CREATE TABLE statement to fit your needs. An easier way to generate the CREATE TABLE statement is to right-click the table name in Enterprise Manager, choose Copy, switch to Query Analyzer, and choose Paste from the Edit menu (or simply drag it from Enterprise Manager to the Query Analyzer).

You'll find that Profiler-generated tables list an event as a representative decimal code and not the name of the event. However, you can run the SQL Server 7.0 extended stored procedure xp_trace_geteventnames with no parameters to list all event classes and their names. First, create a simple table, and send xp_trace_geteventnames' output to that table, as in Listing 1. Then join your trace output table to get the event names, as in Listing 2.

Also from the General tab, you can select whether the trace definition is private or shared with anyone who logs on to the computer. (You can also set a default of private or shared from Profiler's Trace Options dialog box before defining the trace. That way, you don't need to modify this option on the General tab unless you want to change the default.)

From the Source

Finally, the General tab lets you select the source server, which is the SQL Server implementation you want to trace events from. Profiler also gives you options for managing the event queues on the source server. You access these options by clicking the computer icon next to the source server name, which displays the Source Server dialog box and the following source server options:

Number of rows to buffer on server. This option lets you select the maximum number of rows on the server queue. The default is 1000, but you can select from 1 to 20,000.

Server time-out (seconds). If the queue buffer gets full and stays full for the number of seconds you define in this option, Profiler writes a record to the queue, specifying that the queue buffer is full and causing event producers to stop sending events to the queue. The default timeout value is 5 seconds; the value range is from 1 to 10 seconds.

Boost priority (%). This option specifies the queue buffer percentage you must reach before Profiler boosts the priority of the consumer thread that collects events from the queue. In other words, this option sets the buffer percentage at which the consumer process starts collecting events from the queue faster. When Profiler stops tracing events because of a full buffer, lowering the Boost priority value (instead of increasing the queue buffer size or the timeout value) will keep the queue from taking up more queue buffer space. The default value for this option is 95 percent.

Reduce priority (%). In contrast to Boost priority, this option determines the queue buffer percentage at which SQL Server decreases the priority of the consumer thread that collects events from this queue. The default value for this setting is 90 percent.

Don't Stop Now

Profiler's wide range of tracing capabilities makes it a powerful investigative tool. But don't stop with the graphical trace definition. We're just getting started with Profiler and SQL Server 7.0's other tracing functions. "Problem-Solving with SQL Profiler" digs into replaying traces, defining traces with SQL Server's extended stored procedures for traces, and more.