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

• Microsoft SQL Server, version 6.5

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 of code is executed, and recording the results so that the slow parts of the code can be identified. Then the code can be rewritten to be faster and more efficient. Profiling Transact-SQL code in SQL Server is sometimes difficult. However, profiling can provide the following information, which is 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.

MORE INFORMATION

This article defines some common methods to profile Transact-SQL code in SQL Server, if the following assumptions are true:

• SQL Server is not compute-bound as defined in the following article in the Microsoft Knowledge Base:

        ARTICLE-ID: Q111405
        TITLE     : 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:

        ARTICLE-ID: Q165951
        TITLE     : INF: Result Processing for SQL Server
  
  

The rest of this article is split into the following sections to make it more understandable:

1. Simple Transact-SQL Time Profiling

PART 1: Simple Transact-SQL Time Profiling

To perform a basic time performance test of a query such as "SELECT * FROM authors", you can wrap it in the following code:

   DECLARE @x datetime
   SELECT @x = GetDate()
   SELECT * FROM authors
   SELECT DateDiff(millisecond, @x, GetDate())

• 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.

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

The following is an example stored procedure that is used as a basis in both Parts 2 and 3 of this article to display these methods:

   CREATE PROCEDURE timeme AS
   SELECT * FROM pubs..authors
   RETURN
   GO

   CREATE TABLE profile
   (id int primary key,
      trials int not null default 0,
      trltime int not null default 0)
   GO

   /* 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

   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

   INSERT profile (id) VALUES (Object_ID('timeme'))
   GO
   EXEC timeme
   GO
   SELECT Object_Name(id), trltime / trials FROM profile
   GO

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

   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

   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

   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 as described above, consider the following: