INF: How to Profile Transact-SQL Code in Stored Procedures and Triggers

This article was previously published under Q172117
This article has been archived. It is offered "as is" and will no longer be updated.
SUMMARY
Profiling is used to tune code to make it more efficient or faster.Profiling is done by timing and counting the number of times a piece ofcode is executed, and recording the results so that the slow parts of thecode can be identified. Then the code can be rewritten to be faster andmore efficient. Profiling Transact-SQL code in SQL Server is sometimesdifficult. However, profiling can provide the following information, whichis sometimes necessary:
  • The number of times a stored procedure or trigger is run.
  • The amount of time (including maximum and minimum times) a stored procedure or trigger takes to run.
  • The amount of time (including maximum and minimum times) an individual command in a stored procedure or trigger takes to run.
To provide some profiling capabilities, SQL Server provides the SETSTATISTICS TIME and SET STATISTICS IO commands, as well as the followingcolumns in the system table: sysprocesses, cpu, physical_io and last_batch,However, using these options may require changes to applications to handlethe new results. This article provides methods you can use so that theclient applications do not need to change; the stored procedures andtriggers that the application uses are changed instead.
MORE INFORMATION
This article defines some common methods to profile Transact-SQL code inSQL Server, if the following assumptions are true:
  • SQL Server is not compute-bound as defined in the following article in the Microsoft Knowledge Base:
    111405 : INF: SQL Server and Windows NT Thread Scheduling
  • All clients are processing rows efficiently and correctly, according to the following article in the Microsoft Knowledge Base:
    165951 : INF: Result Processing for SQL Server
Before proceeding, please note that profiling or debugging code does affectthe amount of time the code takes to run.

The rest of this article is split into the following sections to make itmore understandable:
  1. Simple Transact-SQL Time Profiling
  2. Simple Table-Based Stored Procedure and Trigger Profiling
  3. Advanced Table-Based Stored Procedure and Trigger Profiling
  4. Sample Stored Procedure to Manage Advanced Table-Based Profiling
  5. Additional Profiling Considerations

PART 1: Simple Transact-SQL Time Profiling

To perform a basic time performance test of a query such as "SELECT * FROMauthors", you can wrap it in the following code:
   DECLARE @x datetime   SELECT @x = GetDate()   SELECT * FROM authors   SELECT DateDiff(millisecond, @x, GetDate())				

This method is very useful, but it does have some limitations. This method:
  • Requires that the client application handles the results set of the second SELECT statement.
  • Does not track the time over multiple runs of the query.
  • Does not work well in stored procedures and triggers.
To resolve these limitations, you can use a profile table to hold resultsso that the average run time, as well as the number of times it was run,can be computed. Part 2 discusses this method below.

PART 2: Simple Table-Based Stored Procedure and Trigger Profiling

The following is an example stored procedure that is used as a basis inboth Parts 2 and 3 of this article to display these methods:
   CREATE PROCEDURE timeme AS   SELECT * FROM pubs..authors   RETURN   GO				

To perform time performance tests of a stored procedure or trigger, a tablewith the following definition is required:
   CREATE TABLE profile   (id int primary key,      trials int not null default 0,      trltime int not null default 0)   GO				

The following code would be added to the stored procedure to recordperformance:
   /* Add this code at the beginning of the stored procedure. */    DECLARE @x datetime   SELECT @x = GetDate()   /* Add this code at the end of the stored procedure. */    UPDATE profile SET trials = trials + 1, trltime = trltime +   DateDiff(MILLISECOND, @x, GetDate()) WHERE id = @@procid				

The following is the modified stored procedure with the performance codeadded:
   CREATE PROCEDURE timeme AS   DECLARE @x datetime   SELECT @x = GetDate()   SELECT * FROM pubs..authors   UPDATE profile SET trials = trials + 1, trltime = trltime +   DateDiff(MILLISECOND, @x, GetDate()) WHERE id = @@procid   RETURN   GO				

Finally, the following is the execution of the stored procedure with theresult of adding the stored procedure to the profile table as well asreporting the performance:
   INSERT profile (id) VALUES (Object_ID('timeme'))   GO   EXEC timeme   GO   SELECT Object_Name(id), trltime / trials FROM profile   GO				

This method is very useful but still has the limitation that profiling isnot easily enabled and disabled. To resolve this limitation, the profiletable needs to hold an enabled status, and the procedure needs to check ifit should be profiled. Part 3 discusses this method below.

PART 3: Advanced Table-Based Stored Procedure and Trigger Profiling

The following is the updated profile table script for dynamic profiling:
   CREATE TABLE profile   (id int primary key,      enabled int not null default 0,      trials int not null default 0,      trltime int not null default 0)   GO				

The following is the updated stored procedure for dynamic profiling:
   CREATE PROCEDURE timeme AS   DECLARE @debug int   SELECT @debug = enabled FROM profile WHERE id = @@procid   IF @debug = 1   BEGIN      DECLARE @ttime datetime      SELECT @ttime = GetDate()   END   SELECT * FROM pubs..authors   IF @debug = 1      UPDATE profile SET trials = trials + 1, trltime = trltime +      DateDiff(MILLISECOND, @ttime, GetDate())      WHERE id = @@procid   RETURN   GO				

Finally, the following is the execution of the stored procedure with theresult of adding the stored procedure to the profile table as well asreporting the performance:
   INSERT profile (id) VALUES (Object_ID('timeme'))   GO   /* This run is not profiled because enabled is 1. */    EXEC timeme   GO   UPDATE profile SET enabled = 1 WHERE id = Object_ID('timeme')   GO   EXEC timeme   GO   SELECT Object_Name(id), trltime / trials FROM profile   GO				

PART 4: Sample Stored Procedure to Manage Advanced Table-Based Profiling

   CREATE PROCEDURE resetprofile AS   /* Disables and effectively resets profiling data for all objects. */    DELETE profile   RETURN   GO   CREATE PROCEDURE setupprofile @name char(30) = NULL AS   /* Adds a stored procedure or trigger to profile table. */    IF @name IS NULL      PRINT 'usage: setupprofile <procedure or trigger name>'   ELSE      IF Object_ID(@name) IS NOT NULL         INSERT profile(id) VALUES (Object_ID(@name))      ELSE         PRINT 'Invalid object name'   RETURN   GO   CREATE PROCEDURE enableprofile @name char(30) = NULL as   /* Enables one or more stored procedures or triggers in the profile   table for profiling. */    IF @name IS NULL      UPDATE profile SET enabled = 1   ELSE      IF Object_ID(@name) IS NOT NULL         UPDATE profile SET enabled = 1 WHERE id = Object_ID(@name)      ELSE         PRINT 'Invalid object name'   RETURN   GO   CREATE PROCEDURE disableprofile @name char(30) = NULL AS   /* Disables one or more stored procedures or triggers in the profile   table for profiling. */    IF @name IS NULL      UPDATE profile SET enabled = 0   ELSE      IF Object_ID(@name) IS NOT NULL         UPDATE profile SET enabled = 0 WHERE id = Object_ID(@name)      ELSE         PRINT 'Invalid object name'   RETURN   GO   CREATE PROCEDURE reportprofile AS   /* Reports performance of enabled stored procedures and triggers. */    SELECT name = Object_Name(id),  'trial avg' = CASE WHEN trials <> 0 THEN   trltime / trials ELSE 0 END, trials FROM profile WHERE enabled = 1   RETURN   GO				

So you can change the run code of Part 3 above to the following:
   EXEC setupprofile 'timeme'   GO   /* This run is not profiled because enabled is 0. */    EXEC timeme   GO   EXEC enableprofile 'timeme'   GO   EXEC timeme   GO   EXEC reportprofile   GO				

PART 5: Additional Profiling Considerations

When performing Transact-SQL profiling with a table for results asdescribed above, consider the following:
  • Because object ids in SQL Server are not unique across databases, it is suggested for profiling in multiple databases to create the profiling table in each database to profile from the same database.
  • Creating the profile table so that there is only one row per page by padding the table with char(250) columns will prevent concurrency problems on the profile table. The following is an example of the padded profile table:
          CREATE TABLE profile      (id int primary key,         enabled int not null default 0,         trials int not null default 0,         trltime int not null default 0,         fill1 char(250) not null default '',         fill2 char(250) not null default '',         fill3 char(250) not null default '',         fill4 char(250) not null default '')      GO						
  • To keep the profile table updates from altering performance as much as possible, lock the table into memory by using either the DBCC PINTABLE command or the sp_tableoption stored procedure with the pintable option. This has the added advantage that the profile table updates are not affected if the server is disk IO bound.


  • If a stored procedure or trigger that is being profiled is run in parallel by multiple clients, normal blocking may occur on the profile table.
  • If the stored procedures and triggers have multiple Return commands, each one needs to perform the profiling check and possibly update the profile table. If this is the case, the Goto command works well to simplify the profiling code. The following is an example of a stored procedure that has multiple Return commands:
          CREATE PROCEDURE timeme AS      IF DB_Name() <> 'pubs'         RETURN      SELECT * FROM authors      RETURN      GO						
    The following is the stored procedure with profiling code also handling the Return commands:
          CREATE PROCEDURE timeme AS      DECLARE @debug int      SELECT @debug = enabled FROM profile WHERE id = @@procid      IF @debug = 1      BEGIN         DECLARE @ttime datetime         SELECT @ttime = GetDate()      END      IF DB_Name() <> 'pubs'         --RETURN         GOTO ENDME      SELECT * FROM pubs..authors      ENDME:      IF @debug = 1         UPDATE profile SET trials = trials + 1, trltime = trltime +         DateDiff(MILLISECOND, @ttime, GetDate())         WHERE id = @@procid      RETURN      GO						
  • The conditional check "IF @debug" should not noticeably alter performance, unless the profiled stored procedure or trigger does not perform any physical disk IO.
  • Profiling maximum and minimum trial timings can also be recorded by making the following changes:

    Change the profile table by adding four columns:
          CREATE TABLE profile      (id int primary key,         enabled int not null default 0,         trials int not null default 0,         trltime int not null default 0,         tmin int not null default 1000000, -- minimum trial time         tmax int not null default 0,      -- maximum trial time         tmint int not null default 0,     -- trial number of minimum trial         tmaxt int not null default 0,     -- trial number of maximum trial         fill1 char(255) not null default '',         fill2 char(255) not null default '',         fill3 char(255) not null default '',         fill4 char(255) not null default '')      GO						
    The changes to the stored procedure are to get the minimum and maximum trial times when checking if it should be profiled. Also, one of three updates is run, based on if the current trial is the new minimum, new maximum, or just another trial.
          CREATE PROCEDURE timeme AS      DECLARE @debug int      DECLARE @min int      DECLARE @max int      SELECT @debug = enabled, @min = tmin, @max = tmax FROM profile WHERE      id = @@procid      IF @debug = 1      BEGIN         DECLARE @ttime datetime         DECLARE @itime int         SELECT @ttime = GetDate()      END      SELECT * FROM pubs..authors      IF @debug = 1      BEGIN         SELECT @itime = DateDiff(MILLISECOND, @ttime, GetDate())         SELECT @itime         IF @min > @itime            UPDATE profile SET trials = trials + 1, trltime = trltime +            @itime, tmin = @itime, tmint = trials               WHERE id = @@procid         ELSE            IF  @max < @itime               UPDATE profile SET trials = trials + 1, trltime = trltime +               @itime, tmax = @itime, tmaxt = trials                  WHERE id = @@procid            ELSE               UPDATE profile SET trials = trials + 1, trltime = trltime +               @itime  WHERE id = @@procid      END      RETURN      GO						
  • Profiling individual commands or sections of a stored procedure or trigger can also be recorded by making the following changes:

    The change to the profile table is to add a trial counter and a trial time column for each additional section or command that needs to be profiled.
          CREATE TABLE profile      (id int primary key,         enabled int not null default 0,         trials int not null default 0,         trltime int not null default 0,         t1 int not null default 0,         t1time int not null default 0,         t2 int not null default 0,         t2time int not null default 0,         fill1 char(255) not null default '',         fill2 char(255) not null default '',         fill3 char(255) not null default '',         fill4 char(255) not null default '')      GO						
    The following is a sample stored procedure to use as a basis for this method:
          CREATE PROCEDURE timeme AS      SELECT * FROM pubs..authors      SELECT * FROM pubs..titleauthor      SELECT * FROM pubs..titles      RETURN      GO						
    Assume that you want to know the total time for the procedure, the first two queries, and only the first query. The following stored procedure is modified to profile this information:
          CREATE PROCEDURE timeme AS      DECLARE @debug int      SELECT @debug = enabled FROM profile WHERE id = @@procid      IF @debug = 1      BEGIN         DECLARE @ttime datetime         DECLARE @t1time datetime         DECLARE @t2time datetime         DECLARE @t1 int         DECLARE @t2 int         SELECT @ttime = GetDate()      END      IF @debug = 1      BEGIN         SELECT @t1time = GetDate()         SELECT @t2time = GetDate()         SELECT * FROM pubs..authors         SELECT @t1 = DateDiff(MILLISECOND, @t1time, GetDate())      END      SELECT * FROM pubs..titleauthor      IF @debug = 1         SELECT @t2 = DateDiff(MILLISECOND, @t2time, GetDate())      SELECT * FROM pubs..titles      IF @debug = 1         UPDATE profile SET trials = trials + 1, trltime = trltime +         DateDiff(MILLISECOND, @ttime, GetDate()), t1time = t1time + @t1,         t1 = t1 + 1, t2time = t2time + @t2, t2 = t2 + 1         WHERE id = @@procid      RETURN      GO						
    Note that this method can also profile performance of extended stored procedure calls as well as remote stored procedure calls.
For using SQL Server 7.0, the following modifications should be made
to the profiling table:
  • Do not use character fill columns to force one row per page.
  • Use Update Row Level Locking.
tsql transql t-sql tran-sql rpc RPCs
Properties

Article ID: 172117 - Last Review: 12/04/2015 17:31:50 - Revision: 3.0

Microsoft SQL Server 6.5 Standard Edition

  • kbnosurvey kbarchive kbcode kbhowto kbinfo kbprogramming kbusage KB172117
Feedback