Troubleshooting and Performance Tuning with SQL Server Traces
A couple of weeks ago I wrote a post (How to Change Database Settings with the PDO_SQLSRV Driver) that highlighted a problem that came up at the November JumpIn! Camp in Redmond. To get to the root of the problem (and eventually a solution), I used SQL Profiler to monitor events on my database server. Of course, monitoring server events can be helpful in troubleshooting any issue, including performance issues, when it comes to data-driven applications. Unfortunately, SQL Profiler (a tool that allows you to easily monitor server activity) is not included as part of SQL Server Express. Fortunately, SQL Profiler is just a nice UI for functionality that is built into SQL Server (including the Express version). So, in this post I’ll show you how to create, read from, and write to a trace file using SQL and SQL Server Management Studio (which you can download for free from here).
Note: While SQL Profiler is not included with SQL Server Express, it is included in the Developer version, which sells for about $50 (and I’ve seen slightly better prices on Amazon).
1. Create a trace. Open SQL Server Management Studio and execute the Transact-SQL below. Note that the sp_trace_create stored procedure is used to create a trace (see the sp_trace_create documentation for a detailed description of the stored procedure and its parameters). The code below will create a trace file (Trace.trc) in the C:\Users\Public\Documents folder. The .trc extension will be appended automatically to the trace file name. The file should not already exist.
/* Declare variables used in trace creation */
declare @rc int -- Return Code for sp_trace_create
declare @TraceID int -- Trace ID created by sp_trace_create
declare @maxfilesize bigint -- Max size in MB for trace file
set @maxfilesize = 5/* Create the trace. */
exec @rc = sp_trace_create @TraceID output,
0,
N'C:\Users\Public\Documents\Trace',
@maxfilesize,
NULL
2. Set the events to be monitored. The hardest part in setting up a trace is in deciding what information you want to collect. The sp_trace_setevent stored procedure is used to set the events to be monitored (see the sp_trace_setevent documentation for more info). If you follow that link to the documentation you’ll see that there is a long list of events that you can collect information about. And, for each event, you have to decide what information you want to collect (see the @columnid parameter in the documentation). To keep things relatively simple, the Transact-SQL below collects some information for the RPC:Starting, RPC:Completed, SQL:BatchStarting, SQL:BatchCompleted, SQL:StmtStarting, and SQL:StmtCompleted events. For each event, I’m collecting information about TextData, ApplicationName, Duration, Reads, Writes, and CPU usage.
-- Set the events
declare @on bit
set @on = 1--RPC:Completed (10)
exec sp_trace_setevent @TraceID, 10, 1, @on --TextData
exec sp_trace_setevent @TraceID, 10, 10, @on --ApplicationName
exec sp_trace_setevent @TraceID, 10, 13, @on --Duration
exec sp_trace_setevent @TraceID, 10, 16, @on --Reads
exec sp_trace_setevent @TraceID, 10, 17, @on --Writes
exec sp_trace_setevent @TraceID, 10, 18, @on --CPU--RPC:Starting (11)
exec sp_trace_setevent @TraceID, 11, 1, @on --TextData
exec sp_trace_setevent @TraceID, 11, 10, @on --ApplicationName
exec sp_trace_setevent @TraceID, 11, 13, @on --Duration
exec sp_trace_setevent @TraceID, 11, 16, @on --Reads
exec sp_trace_setevent @TraceID, 11, 17, @on --Writes
exec sp_trace_setevent @TraceID, 11, 18, @on --CPU--SQL:BatchCompleted (12)
exec sp_trace_setevent @TraceID, 12, 1, @on --TextData
exec sp_trace_setevent @TraceID, 12, 10, @on --ApplicationName
exec sp_trace_setevent @TraceID, 12, 13, @on --Duration
exec sp_trace_setevent @TraceID, 12, 16, @on --Reads
exec sp_trace_setevent @TraceID, 12, 17, @on --Writes
exec sp_trace_setevent @TraceID, 12, 18, @on --CPU--SQL:BatchStarting (13)
exec sp_trace_setevent @TraceID, 13, 1, @on --TextData
exec sp_trace_setevent @TraceID, 13, 10, @on --ApplicationName
exec sp_trace_setevent @TraceID, 13, 13, @on --Duration
exec sp_trace_setevent @TraceID, 13, 16, @on --Reads
exec sp_trace_setevent @TraceID, 13, 17, @on --Writes
exec sp_trace_setevent @TraceID, 13, 18, @on --CPU--SQL:StmtStarting (40)
exec sp_trace_setevent @TraceID, 40, 1, @on --TextData
exec sp_trace_setevent @TraceID, 40, 10, @on --ApplicationName
exec sp_trace_setevent @TraceID, 40, 13, @on --Duration
exec sp_trace_setevent @TraceID, 40, 16, @on --Reads
exec sp_trace_setevent @TraceID, 40, 17, @on --Writes
exec sp_trace_setevent @TraceID, 40, 18, @on --CPU--SQL:StmtCompleted (41)
exec sp_trace_setevent @TraceID, 41, 1, @on --TextData
exec sp_trace_setevent @TraceID, 41, 10, @on --ApplicationName
exec sp_trace_setevent @TraceID, 41, 13, @on --Duration
exec sp_trace_setevent @TraceID, 41, 16, @on --Reads
exec sp_trace_setevent @TraceID, 41, 17, @on --Writes
exec sp_trace_setevent @TraceID, 41, 18, @on --CPU
3. Filter trace data. You can use the sp_trace_setfilter stored procedure to filter data that is captured by the trace. (See the sp_trace_setfilter documentation for more information.) The T-SQL below configures my trace so that I will only see activity for the TestDB database. Without this filter, I will see activity for the entire server (including activity that goes on when the server is idle).
/* Collect only TestDB activity */
exec sp_trace_setfilter @TraceID, 35, 0, 0, N'TestDB'
4. Start the trace. After executing the T-SQL above, execute the T-SQL here, which turns on the trace by calling sp_trace_setstatus (see sp_trace_setstatus docs for more info):
/* Set the trace status to start */
exec sp_trace_setstatus @TraceID, 1
5. Read trace data. Now run your PHP scripts that hit SQL Server. To see the trace data after running the scripts, execute the following T-SQL:
SELECT EventClass, TextData, ApplicationName,
CPU, Reads, Writes, Duration
FROM sys.fn_trace_gettable('C:\Users\Public\Documents\Trace.trc', NULL)
Just to see an example of what data the trace collected, I ran this simple PHP script:
$server = "ServerName\sqlexpress";
$connOptions = array("Database"=>"TestDB", "UID"=>"User", "PWD"=>"Password");$conn = sqlsrv_connect($server, $connOptions);
$param1 = 1;
$param2 = 'data1';
$params = array( &$param1, &$param2);$stmt1 = sqlsrv_prepare($conn, "INSERT INTO Table_1 (id, data) VALUES (?,?)", $params);
for($i=2; $i <= 4; $i++)
{
sqlsrv_execute($stmt1);
$param1 = $i;
$param2 = 'data'.$i;
}sqlsrv_free_stmt($stmt1);
$stmt2 = sqlsrv_query($conn, "SELECT * FROM Table_1");
while($row = sqlsrv_fetch_array($stmt2, SQLSRV_FETCH_ASSOC))
{
print_r($row);
echo "<br/>";
}$stmt3 = sqlsrv_query($conn, "DELETE FROM Table_1");
echo sqlsrv_rows_affected($stmt3)."<br/>";
When I then executed the SELECT statement above in SQL Server Management Studio, here’s what I saw:
The first two event IDs (65528 and 65534) are specific to the trace itself. After that you can see event ID’s that correspond to the events we set in our trace. A couple of notes about some of the columns:
- CPU – Amount of CPU time in milliseconds used by the event.
- Reads – Number of logical disk reads performed by the server on behalf of the event
- Writes – Number of physical disk writes performed by the server on behave of the event.
- Duration – Amount of time taken by the event. Measured in microseconds.
6. Stop and delete the trace. When you are finished collecting data you can stop and delete the trace with the following two calls to the sp_trace_setstatus stored procedure:
exec sp_trace_setstatus @TraceID, 0 -- Stop trace
exec sp_trace_setstatus @TraceID, 2 -- Delete trace
Note that setting the trace status to 2 does not delete the trace file. You can still query that file to look over your trace data as long as that file is still around.
If you are running multiple traces on a a server, the following T-SQL will come in handy in monitoring them (sys.traces is a catalog view that contains the current running traces on the system):
SELECT * FROM sys.traces
To learn more about the stored procedures that are available for creating and configuring traces, see Introducing SQL Trace in the MSDN documentation. Note that running SQL Trace comes with a performance hit because it uses system resources to gather data. However, many things can be done to minimize the performance impact of SQL Trace. For guidance, see Optimizing SQL Trace in the MSDN documentation.
That’s it for today…hope this post was helpful.
Thanks.
-Brian