Tracing in SQL Server or MSDE

3 September 2003

Oakland Software

Often it is useful to determine exactly the SQL calls made to a database. This is particularly useful when developing MS Access applications, both to help diagnose cryptic error messages and to identify performance problems. This paper shows you how to trace SQL calls using command line tools. It does not rely on the SQL Profiler and therefore works with the free MSDE database engine (which is SQL server without the GUI tools).

Note for Access users: this paper is useful only for Access adp projects that use SQL Server/MSDE, it does not cover Access mdb projects that use Jet SQL.

The first part of this paper provides code that you can copy/paste to quickly get started tracing SQL calls. Just follow the instructions. The remainder provides more detail as well as links to resources for a more in-depth understanding of how tracing works.

Running a Trace

To run the trace, you need to start it, then execute the SQL you want to trace, then stop the trace and close the trace files, and then capture the results for analysis. Here is how to do each step. You can just copy each of these sections into osql or your favorite SQL command line tool.

Run this code to start tracing:
declare @traceid int declare @ret int declare @on bit set @on = 1 exec @ret = sp_trace_create @traceid OUTPUT, 6, N'c:\sqltrace' print 'ret (s/b zero): ' + convert(varchar(30), @ret) print 'traceid: ' + convert(varchar(30), @traceid) exec @ret = sp_trace_setevent @traceid, 13, 1, @on exec @ret = sp_trace_setevent @traceid, 33, 1, @on exec @ret = sp_trace_setevent @traceid, 40, 1, @on exec @ret = sp_trace_setstatus @traceid, 1 go
Make sure the return code is zero, and note the traceid. It should be 1 if this is the only trace running. If the return code is not zero, see below for common errors.
If for some reason the traceid is not 1, then make sure and change the traceid in step 3 to use the correct traceid as noted.
Execute the SQL you want to trace. You can execute the SQL using any normal means (running Access for example).
Run this code to shutdown the tracing and make the file available. The trace file is not actually written until both the tracing activity is stopped and the trace is destroyed.

If the traceid is not 1, change the first argument to each of the stored procedures to the correct traceid:
exec sp_trace_setstatus 1, 0 exec sp_trace_setstatus 1, 2 go
Print the results of the trace:
select EventClass, cast(TextData as char(80)) from ::fn_trace_gettable(N'c:\sqltrace.trc', -1) go
Optionally run this code to capture the trace output into a temporary table for further analysis.
drop table temp1 go select TextData, EventClass into temp1 from ::fn_trace_gettable(N'c:\sqltrace.trc', -1) go
If you are using Access you can just open the temporary table to view your trace.

Example Session

Here is a session using the above statements and showing the execution of some sample statements:


1> declare @traceid int

2> declare @ret int

3> declare @on bit

4> set @on = 1

5> exec @ret = sp_trace_create @traceid OUTPUT, 6, N'c:\sqltrace'

6> print 'ret (s/b zero): ' + convert(varchar(30), @ret)

7> print 'traceid: ' + convert(varchar(30), @traceid)

8> exec @ret = sp_trace_setevent @traceid, 13, 1, @on

9> exec @ret = sp_trace_setevent @traceid, 33, 1, @on

10> exec @ret = sp_trace_setevent @traceid, 40, 1, @on

11> exec @ret = sp_trace_setstatus @traceid, 1

12> go

ret (s/b zero): 0

traceid: 1



1>

2> select count(*) from people

3> go



 -----------

        6303



(1 row affected)



1> select lastname, firstname from people where lastnameoops = "upton"

2> go

Msg 207, Level 16, State 3, Server REPOMAN, Line 1

Invalid column name 'lastnameoops'.



1> select lastname, firstname from people where lastname = "upton"

2> go

 lastname

        firstname

 --------------------------------------------------

        --------------------------------------------------

 Upton

        Sue

 Upton

        Francis



(2 rows affected)



1> exec sp_trace_setstatus 1, 0

2> exec sp_trace_setstatus 1, 2

3> go

1>  select EventClass, cast(TextData as char(80)) from ::fn_trace_gettable(N'c:\sqltrace.trc', -1)

2> go

 EventClass

 ----------- --------------------------------------------------------------------------------

          13

select count(*) from people



          40 select count(*) from people



          13 select lastname, firstname from people where lastnameoops = "upton"



          33 Error: 207, Severity: 16, State: 3

          13 select lastname, firstname from people where lastname = "upton"



          40 select lastname, firstname from people where lastname = "upton"



          13  exec sp_trace_setstatus 1, 0

exec sp_trace_setstatus 1, 2



(8 rows affected)

Common Problems

The main problem you could have with the sp_trace_create stored procedure is getting a "12" return code that indicates the output trace file could not be created. This could either be that the file is already present (the tracing mechanism will not overwrite a file, you must delete it first), or because there is another open trace. To determine the open traces, do:
SELECT traceid,property,cast(value as char(50)) FROM :: fn_trace_getinfo(default) go

Other return codes are shown in the sp_create_trace stored procedure documentation.

The Details

Let's go though the steps mentioned above in more detail so you can better understand how tracing works:

Create the trace (sp_create_trace)
This essentially defines the file that is to contain the trace output. The file must not already be present, nor associated with another trace. It returns a traceid that is used in subsequent calls related to the trace.
Set the events you want to trace (sp_set_event)
This indicates the types of things you are interested in tracing. The most common events are:
- 13 - An Transact-SQL batch is starting. This shows all of the statements given to the server, even if they have an error during execution. This is useful to see exactly what is being sent to the server.
- 33 - Exception. Shows any type of error condition that has happened at the server, including the results of invalid statements. The statement that caused the error will immediate precede this record and have an event type of 13.
- 40 - Statement Execution. Shows the beginning of the execution of a statement that does not have an error.
There are many other events, all shown on the sp_set_event page that provide much more detailed information. But most of these are administrative. In addition, there are many different types of information you can get about these events, but the TextData column (column 1) is generally all that is needed for the purposes of tracing SQL.
Start the trace (sp_trace_setstatus).
Calling this stored procedure with an argument of 1 makes the tracing start to record events.
Stop the trace (sp_trace_setstatus).
Calling this stored procedure with an argument of 0 stops recording events. You may subsequently call it again with 1 to restart recording.
Close the trace file (sp_trace_setstatus).
Calling this stored procedure with an argument of 2 closes the trace file and destroys the trace. Unless you have closed the trace file, you cannot get at any of the trace events.
Getting the data (fn_trace_gettable).
This function returns the table in which the trace events are captured. It is normally used as part of a SELECT or SELECT INTO statement to further view/process the data.

Further information on tracing is available here on MSDN, but it may not be useful for the command line user, since it focuses on using the GUI SQL profiler interface.