sqtlrace is a stored procedure written by Lee Tudor (a.k.a Mr Tea.) The procedure takes an SQL batch as its first argument, sets up a trace filtered to include the current connection only, runs the batch, and summarises the trace information per statement in the batch. This can be a very handy tool to track down performance bottlenecks in a longer stored procedure, not the least if there are calls to nested procedures.
You can also use sqltrace to capture the query plans from a batch. This makes it possible to capture a single plan in a deep chain of nested stored procedures without drowning in all the other plans. This is particularly convenient with SSMS 2008: if you click on the XML document for the plan in grid mode, the graphical plans open directly. (With SSMS 2005, you will need to save the XML document with the .sqlplan extension and reopen it.) However, this feature is not enabled by default, and you need to use it with care, see further the section Including Query Plans.
Get the source code to sqltrace here. Latest version is SourceSafe version 2, checked in 2008-11-29.
You can put sqltrace in any database. You may prefer to put it in a general utility database; maybe the same database where you have beta_lockinfo. However, in such case you must always include the database name of all objects in the batch you submit to sqltrace, so it may be more convenient to put it in the database where you are working right now.
sqltrace runs on SQL 2005 or later.
The procedure takes a couple of parameters:
| Name | Type | Default | Description |
|---|---|---|---|
| @batch | The batch to analyse. In many cases this will be call to a stored procedure. Keep in mind that the context within
sqltrace is the database where sqltrace resides. Thus, to trace procedures in asother database, you need to use
three-part notation for all objects – even if you invoke sqltrace from the database where your procedure resides.
Say that you have put sqltrace in the util database, and you are now in the Webshop database and want to trace the
procedure get_orders. You need to say:
EXEC util..sqltrace 'EXEC Webshop..get_orders 123'If you leave out "Webshop.." you will get an error saying that get_orders is missing. | ||
| @minReads | bigint | 1 | In the trace, only include statements with this many reads. The default is set to exclude trivial statements like variable assignments, IF statements etc. |
| @minCPU | int | 0 | In the trace, only include statements that take this much CPU. The unit is ms. |
| @minDuration | bigint | 0 | In the trace, only include statements with a duration over this value. Note that the unit is µs. See also the section An Issue with Durations. |
| @factor | varchar(50) | 'Duration' | The measure for the column Factor in the result set. Can be one of Reads, Writes, Duration and CPU. See further this column below. |
| @order | varchar(50) | '' | Output order for the result set. Can be blank, or one of Reads, Writes, Duration and CPU. When blank, the result set is ordered by first occurrence. Else it is ordered by the requested column in descending order. |
| @plans | varchar(50) | '' | Whether to include execution plans in the output. Can be any of blank, Estimated or Actual. See further below in the section Including Query Plans. |
| @rollback | bit | 0 | Put the batch in a transaction and roll back when its done. The ROLLBACK is not included in the trace. |
| @timeout | int | 300 | For how long time the trace is to run.
Use this parameter if you expect your batch to run for more than five minutes. Normally, sqltrace stops the trace when the batch completes. However, if the batch is aborted because of an error, or because you cancel the query, the trace keeps running. The traces defined by sqltrace do incur some load on the server, particularly if you have opted to include execution plans. Thus, to avoid that a runaway trace incurs a hog on your system, sqltrace by default sets a stop time for the trace. |
By default, sqltrace writes the trace files to C:\TEMP. If you prefer a different location, just change this in the source code. The name of the trace file is just a GUID. sqltrace does not remove the file when it's done, so you may want to clean up the directory every once in a while.
You need to make sure that the directory exists, and that the service account for SQL Server has permission to write to that directory.
In the result set, each executed statement normally appears only once, but if there is recursion, each nesting level will appear on a row of its own. If you specify a value for @plans, this can also affect the grouping, see below in the section Including Query Plans.
These are the output columns:
| Name | Description |
|---|---|
| Factor | The total percent of the chosen measure taken by this statement. See the parameter @factor above. Blank if the percentage is 0. If the total of @factor is 0, Factor will be blank for all columns. |
| Text | The text of the statement |
| Calls | Number of times this statement was executed if more than 1. |
| Nesting | On which nesting level the statement was executed. |
| SQL module and line number for the statement. | |
| Duration | Duration for the statement in milliseconds with three decimals. See also the section An Issue with Durations. |
| Reads | Number of reads for the statement according to the trace. Blank when 0. |
| Writes | Number of writes for the statement according to the trace. Blank when 0. |
| CPU | CPU time for the statement in milliseconds. Blank when when 0. |
| Compiles | Number of recompiles for the statement if any. |
| Reason | Reason why the statement was recompiled. See the table below for the meaning of the codes. |
| rcDuration | Time spent on recompiling the statement. This value is derived from the execution plan, and thus only populated if you supply a value for @plans. The value is in milliseconds. The value for the batch itself – which has sqltrace as the object – has the total recompilation time for the batch. |
| rcCPU | CPU time for the recompilation of the statement. Like rcDuration, only populated if you included execution plans in the trace. |
| XPlan | The execution plan for the statement. Blank if you did not specify a value for @plans. |
By default, the order of the statements in the output follows their first appearance in the trace. You can use the @order parameter to get the statements listed by Duration, Reads, CPU or Writes in descending order to find any resource hog quickly.
This table details the codes in the Reason column. SubClassNo is the EventSubClass column in the trace. The descriptions are taken from Books Online.
| Code | SubClassNo | Description |
|---|---|---|
| Local | 1 | Schema changed. |
| Stats | 2 | Statistics changed. |
| DNR | 3 | Deferred compile. |
| SET | 4 | SET option changed. |
| Temp | 5 | Temp table changed. |
| Remote | 6 | Remote rowset changed. |
| Browse | 7 | FOR BROWSE permissions changed. |
| QN | 8 | Query notification environment changed. |
| MPI | 9 | Partitioned view changed. |
| Cursor | 10 | Cursor option changed. |
| Manual | 11 | Option(RECOMPILE) or WITH RECOMPILE requested. |
With the parameter @plans, you can select to include query plans in the trace. This can be very useful, if your batch is long and produces lots of plans of which many are dull and uninteresting, and you want to look at a specific plan without having the Execution Plan tab in Mgmt Studio cluttered by all the other plans.
There are two permitted values for this parameter: Estimated and Actual. An estimated plan includes only the estimates that the optimizer works with to determine the plan, whereas the actual plan includes the actual execution values. Often poor plans are due to poor estimates, why it is very useful to see the actual values.
You need to use this feature with care. There are several things to consider:
The columns rcDuration and rcCPU are only populated when you set @plan, as these values are taken from the XML document for execution plan.
When SQL 2005 came out, one piece of news was that the Duration column in a trace was in microseconds, although Profiler by default presents it in milliseconds. However, Microsoft by time realised that the timer they used to achieve this is not accurate, and with SQL 2005 SP3 and SQL 2008 they have taken a half step backwards, and now use interrupt ticks. These are typically approxamitely 1 ms, but the exact value depends on your hardware.
A consequence of this is that if you run sqltrace on SQL 2005 SP2, you will see durations of 30 µs and alike. On SQL 2005 SP3 and SQL 2008, these statements will typically show 0 for the duration. In a similar vein, durations for short events may display as 1.000, 2.000, 13.001 and so on.
For more information on this issue see this blog post from Bob Dorr, Senior SQL Server Escalation Engineer and KB Article 931279.
If you have any comments on sqltrace, contact me on esquel@sommarskog.se or Lee Tudor directly on mr__tea@hotmail.com.
2008-11-29 – First release posted on my web site.