Problem-Solving with SQL Profiler

Using SQL Server 7.0's SQL Profiler tracing tool is like having a private investigator at your fingertips to help tune, troubleshoot, and manage your SQL Server environment. "Trace That Event with SQL Profiler,"  outlines SQL Server 7.0's trace architecture and shows you how to graphically define a trace with Profiler. You're now ready to dive into deeper waters: replaying Profiler traces and defining autostart traces with SQL Server 7.0's extended stored procedures for tracing. With this firm foundation, you can put Profiler and these extended stored procedures to work investigating everything from long-running queries to deadlocks.

Before the Replay

With Profiler, you can replay saved traces to debug problem applications, provide production-like scripts for test environments, tune databases, and more. But if you want to replay traces, you need to do some up-front work. First, you must define a trace to capture certain events and data columns besides the ones you're interested in. These extra events and data columns ensure that you replay the scenarios exactly as they happened. Second, you must save the trace output to a file, a table, or an SQL script.

All replays require you to capture the Connect, Disconnect, ExistingConnection, and RPC:Starting and SQL:BatchStarting events. In addition, for replays of API server-side cursors (server-side cursors that API cursor functions manage), you must capture the CursorExecute, CursorOpen, and CursorPrepare events. For replays of server-side prepared SQL statements, you add the Exec Prepared SQL and Prepare SQL events. Required data columns for replay are application name, binary data, connection ID or server process ID (SPID), database ID, event class, event subclass, host name, integer data, server name, SQL user name, start time, and text.

Note that a replay doesn't simulate captured events; it re-executes them. So when you replay a trace, you'll likely modify your database. For example, if you replay a trace that includes an INSERT operation, you might find a table with a duplicate key. To keep this problem from happening, revert your database to its initial state if you're replaying the trace against the source server (the server on which you originally traced the events).

If you want to replay the trace on a different server, make sure the database on the target server is in the same state as the one on the source server. You must also use the same logins, users, permissions, and database IDs as you did on the source server.

Using the same database IDs is tricky, especially because Microsoft discourages changing the database ID by directly modifying the sysdatabases system table. To match database IDs, you can copy the user database files from the source server to the same path on the target server, then restore a master database backup from the source server to the target server. Alternatively, you can restore a user database backup from the source server to the target server, then restore the master database backup. Either method ensures that the database files on the target server exist in their original locations and that the master database's system tables contain the original database ID. To avoid the problem entirely, simply remove the database ID data column from the trace and set the target database as the default database for each user the trace captures.

You can also control a script's synchronization level and replay rate. Just choose Settings from the Replay menu to display the Replay SQL Server dialog box. The Synchronization Level, which controls synchronization across connections, supports the following options:

The Replay Rate supports the following options:

Roll the Replay

Let's say you want to replay a trace of server-side prepared SQL statements, which are Transact-SQL (T-SQL) statements the client sends the database through ADO, OLE DB, or ODBC. SQL Server 7.0 implements server-side prepared SQL statements through the pseudo stored procedures sp_prepare and sp_execute, which the client application calls.

A call to sp_prepare causes SQL Server to prepare the T-SQL statements for execution by compiling the statements and caching the statements' execution plans. A call to sp_execute causes SQL Server to execute the precached plans, possibly many times. Each call to the stored procedures generates the RPC:BatchStarting events Prepare SQL and Exec Prepared SQL, which is why you must include these events in your trace definition.

SQL Profiler provides several sample trace definitions you can use as templates, including Sample 6: T-SQL for Replay, which you can use to generate trace output for replay. (See "Using SQL Profiler," July 1999, for more about Profiler's sample traces.) To open saved trace output for replay, select Open from the File menu and supply a trace file, table, or SQL script. You then manage the replay by using the options in Table 1. These options appear either in the Replay menu or as buttons on the toolbar.

Using Extended Stored Procedures

Some tracing functions aren't available from SQL Profiler, including running a trace on a scheduled basis, defining a trace to start when a certain event occurs or when SQL Server starts, and sending trace output to the Windows NT or Windows 2000 (Win2K) application log. To perform these functions and gain more programmatic control of your traces, you can use a set of extended stored procedures called xp_trace*.

To see how to use these extended stored procedures, let's look at a stored procedure to start a trace and a stored procedure to stop a trace. The first stored procedure, sp_start_mytrace, defines the trace's events, data columns, and filters and creates a queue to hold the captured events. It then retrieves the events from the queue and saves them to a system file. The sp_start_mytrace procedure tracks and communicates with the event queue through an integer value called a queue handle, which the procedure assigns when it creates the queue. The sp_stop_mytrace procedure then retrieves this handle to stop the queue.

Keeping track of the queue handle can be tricky. Although many techniques exist to retrieve the value, the easiest and most functional is probably creating a table that tracks all running traces and collects their queue handles, trace start times, and the computers and logins you activated the traces from. Listing 1 shows the statement to create such a table, which I call activetraces. You can check this table to see which traces are running. To stop a trace, you simply query the table for the appropriate query handle.

The Start Trace Stored Procedure

Let's walk through these two stored procedures to see how they use the extended stored procedures for tracing. The stored procedure to start a trace, sp_start_mytrace (available in the"Download the Code" zip file at the top of the page), has four optional input parameters. The first two, @spid_filter and @dbid_filter, let you limit your trace to filters on the specified SPID and database ID. If you don't supply these parameters, the trace captures events for all SPIDs and database IDs. The @email_address parameter lets you specify an email address to which the stored procedure sends a trace detail message when it starts the trace. If you don't specify this parameter, sp_start_mytrace sends the message to the screen only. If you specify this parameter but don't have a valid email profile defined for your server, the stored procedure will send an error message and abort. The last input parameter, @filename, lets you specify a destination file name for the trace. If you don't specify this parameter, the stored procedure generates a destination file name of 'c:mytraceN.trc', with N being the queue handle number. This file-naming convention lets you run multiple traces at the same time without having one trace lock the file for its use.

The sp_start_mytrace procedure first calls extended stored procedure xp_trace_addnewqueue to create the event queue. Addnewqueue's first four parameters—parameters-max_items, timeout, thread_boost, and thread_reduce—are at their default settings. ("Trace That Event with SQL Profiler" explains these parameters for managing event queues.) The procedure's required_columns parameter is a bitmask of the data columns you want to capture. To generate the bitmask, you perform a bitwise OR (|) operation between integer values that represent each data column. The output parameter, queue_handle, holds the queue handle integer for later use.

Sp_start_mytrace then calls extended stored procedure xp_trace_seteventclassrequired for each event you want to capture in the trace. Seteventclassrequired has three parameters. Queue_handle is the queue handle obtained from the xp_trace_addnewqueue stored procedure. Event_class is an integer value that represents the event to capture. (You run the extended stored procedure xp_trace_geteventnames to get the full list of event classes and their names. This example uses Profiler's default event classes.) And Isrequired is a Boolean value that determines whether to include the event in the trace.

After selecting the events to capture, you need to set event filters. By default, the trace definition filters out events that Profiler generates. However, if you want to learn more about SQL Server 7.0's extended stored procedures for tracing, which Profiler uses to run traces, you might want to change the filter on Profiler from exclusion to inclusion. Start the trace, then start another trace of your choice, and you'll see the extended stored procedures Profiler runs to implement the second trace.

Every filter category has a different extended stored procedure, but they all follow the pattern xp_trace_set*filter. The sp_start_mytrace stored procedure uses xp_trace_setappfilter to exclude events Profiler generates. If the user requests filters on SPID or database ID, sp_start_mytrace uses xp_trace_setspid-filter or xp_trace_setdbidfilter.

Next, sp_start_mytrace specifies the output destination for the queue. Although you can have more than one output destination for a queue, you can't have more than one destination of any one output type. For instance, you can output simultaneously to a file and a table but not to two files. Sp_start_mytrace calls xp_trace_setqueuedestination to specify output destination. To select more than one destination, you just repeat the extended stored procedure call. Setqueuedestination's parameters (besides queue_handle) are

Sp_start_mytrace sends the trace output to a file name specified in the @filename parameter on the local server.

Let the Trace Begin

With the trace defined, sp_start_mytrace adds a row to the activetraces table to keep track of the trace as it runs. To make sure the trace queue handle and other information aren't lost, sp_start_mytrace formats a message with the trace detail information, printing it to the screen and emailing it to the server by using extended stored procedure xp_sendmail. Sp_start_mytrace then calls extended stored procedure xp_trace_startconsumer, with a single required parameter of queue handle, to start sending events to the specified output queue.

Listing 2 shows the second stored procedure, sp_stop_mytrace, which stops the trace by using the queue handle. Sp_stop_mytrace retrieves the queue handle by querying the activetraces table, then calls extended stored procedure xp_trace_destroyqueue for the given queue handle to stop the trace. Finally, sp_stop_mytrace deletes from activetraces the row representing the trace.

Testing the Stored Procedures

To test these stored procedures, execute the following batch:

DECLARE @mydbid intDECLARE @myspid intSELECT @mydbid = db_id('pubs'), @myspid = @@spidEXEC sp_start_mytrace @myspid, @mydbid

You should receive a printed message (and an email message, if you specified that parameter) that looks like this:

The following trace has started:Queue Handle: 14Start Time: Dec 19 1999  2:07PMHost: SHIRELogin Name: MIDDLE_EARTHGandalfDestination File: c:mytrace14.trcUse EXEC sp_stop_mytrace 14 to stop it.

Now switch to the Pubs database, and run a few queries against its tables. Make sure you use the same connection that called the stored procedure, because in our test, we retrieve the SPID of the current connection with the system function @@SPID and use that SPID as the trace filter. When you're finished, execute the following statement, replacing 14 with the queue handle you received in the printed and email messages:

sp_stop_mytrace 14

You can now open the generated file in SQL Profiler for review.

Setting a Trace to Autostart

You can manually use these stored procedures to start and stop a trace, or you can set them to run automatically when SQL Server starts or in response to certain events. To set a trace to autostart, you first save its definition by using extended stored procedure xp_trace_savequeuedefinition, then set the trace to autostart by using extended stored procedure xp_trace_setqueueautostart.

Savequeuedefinition requires two parameters in addition to the queue handle. Queue_name identifies the trace. (Savequeuedefinition will save the trace definition under the Registry key HKEY_LOCAL_MACHINESOFTWAREMicrosoft MSSQLServerSQLServerProfilerServerQueues. You load the trace definition later by using extended stored procedure xp_trace_loadqueuedefinition.) And is_shared specifies whether the queue definition is shared (1) or private (0).

Setqueueautostart also requires the queue name and a Boolean value that specifies whether to enable (1) or disable (0) autostarting.

Listing 3 shows the rest of the procedure to set a trace to autostart (note that this code doesn't show the steps already covered). To disable autostarting, run

EXEC xp_trace_setqueueautostart   'My Sample',0 - auto-start? 1 - enable, 0 - disable

In the Trenches

Now that you understand Profiler's tracing functions, you can use them to investigate many database situations. Take long-running queries, for example. To find out why they're taking so long, just define a trace with the relevant completion events, depending on whether you run the queries inside stored procedures or in batches. You usually need to trace the SQL:StmtCompleted and SP:StmtCompleted events. Group the queries by duration or CPU data columns, depending on whether the queries are slower than you'd like or are using more CPU resources than they should. To make sure you don't waste tracing resources on fast queries, you can filter the trace by a minimum number of milliseconds for duration or a minimum number of milliseconds for CPU usage.

You can also use Profiler to find out what's going on behind the scenes in SQL Server Enterprise Manager. Suppose you want to see what Enterprise Manager does when you add the file 'file5' to a filegroup called 'fg5' in the testdb database. First, open testdb's database properties dialog box and add the file. But before clicking OK, set up a trace in Profiler using the default events and data columns and a specific-value filter of 1 (master) on database ID. Start the trace; click OK in Enterprise Manager, then stop the trace. Profiler will capture statements like these:

use [master] ALTER DATABASE [testdb] ADD FILEGROUP [fg5] ALTER DATABASE [testdb] ADD FILE(NAME = N'file5', FILENAME = N'd:MSSQL7DATAfile5_Data.NDF' , SIZE = 1, FILEGROWTH = 10%) TO FILEGROUP [fg5]

In addition, Profiler can help solve problems such as how to get automatic notification when an auto-grow parameter changes. This problem is tricky because you can't place a trigger on a system table. One way to get this information is to use Profiler to define a trace with the following events, data columns, and filters:

You can then create an output table structured as the statement in Listing 4. Note that in this case, you must build a table instead of letting Profiler create it because you need to retrieve the TextData column from a trigger. The problem is that in the Profiler-created table, TextData is the ntext datatype, which is inaccessible from a trigger. To make the column in your table accessible from a trigger, just specify its datatype as nvarchar.

Next, you define a trigger to alert you when an auto-grow parameter changes, as Listing 5 shows. To test the trigger call, change a file's properties:

ALTER DATABASE testdb MODIFY FILE (NAME = 'testdb_dat', MAXSIZE = 30MB)

You'll receive the following email message:

File properties changed:Statement: ALTER DATABASE testdb MODIFY FILE (NAME = 'testdb_dat', MAXSIZE = 30MB)NT User Name: GandalfApplication Name: MS SQL Query AnalyzerSQL User Name: NATime: 1999-12-22 14:15:28

Finding out which events led to a deadlock can be difficult, but Profiler provides some specific events to help. For example, you can trace the Lock:Deadlock event, which tells you a deadlock occurred and specifies the SPID and transaction ID deadlocked, the time the deadlock occurred, and the application and login names. The handy Lock: Deadlock Chain event, generated by each event leading to a deadlock, supplies the SPIDs and transaction IDs involved.

You can record the transaction IDs involved in the deadlock, then group the output by transaction ID and expand only the transactions involved. Or you might consider sending the trace output to a table so you can run queries that filter on a list of SPIDs or transaction IDs.

To generate a deadlock situation, create two tables—t1 and t2—each with one integer column, then in each table, insert a row with a value of 1. Define a trace with the following events: Lock:Deadlock, Lock: Deadlock Chain, and relevant starting and completion statement events (RPC, SP, SQL), depending on the source you suspect. In this example, we need only SQL: StmtStarting and SQL:StmtCompleted.

Besides the default data columns, add the transaction ID and any other data columns you might want. Filter the trace on the database ID of the database you're working on, then open two connections to your server from Query Analyzer. From connection 1, execute:

BEGIN TRANSACTION UPDATE t1 SET col1 = 1

From connection 2, execute:

BEGIN TRANSACTION  UPDATE t2 SET col1 = 1  SELECT * FROM t1COMMIT TRANSACTION

And from connection 1 again, execute:

  SELECT * FROM t2COMMIT TRANSACTION

Stop the trace, and open the trace file. Find the Lock:Deadlock Chain events, and record the transaction IDs involved. Group your output by transaction ID, and expand the relevant transactions. The output should look similar to that in Screen 1.

SQL Server Enterprise Manager provides a wizard that helps you set up traces, including one that helps you identify the cause of a deadlock. You can use the Create Trace Wizard to set up a trace by choosing Wizards from Enterprise Manager's Tools menu. Open the Management category, and choose Create Trace Wizard.

On the Case

SQL Profiler's trace replay capabilities along with SQL Server 7.0's extended stored procedures for tracing provide a wealth of power and flexibility for debugging database problems. Whether you want to simply monitor your SQL Server environment or need to solve some pressing performance mysteries, it's time to put your knowledge into action.