Elapsed Time

If you want to know the elapsed time of a statement, you could use the set statistics time setting, but sometimes the results are unreliable. What’s more, you may be interested in inserting the results in a worktable or displaying them in a particular format. One useful exercise is to run the same query on a busy server at different times of day to see whether the amount of traffic on the server is causing the response time to deteriorate. To do that, you would need a small table to track those timings. I’ve made it a permanent table, but you can make it temporary (especially if you don’t have the permissions to create permanent tables in the database):

create   table   perf_tracker   (
module    varchar(20)    not   null,
execution_id   int    not    null,
step_id   int  not    null,
start_time      datetime,
end_time      datetime,
elapsed    int
)

Now you can add rows to the performance tracking table with an INSERT statement in a stored procedure:

create   proc   show_tracking
a s
--   get execution_id
declare   @exid   int,   @start   datetime
select   @exid  =  isnull(max(execution_id)   +   1,   1)
    from perf_tracker
   where   module   =   “example”
--   get   start   time
select   @start   =   getdate()
select   count(*)   from   titles
-- write out record
insert    perf_tracker
          (module, execution_id, step_id, start_time, end_time, elapsed)
values
        (“example”, @exid, 1, @start, getdate(),
               datediff(ms, @start, getdate()))
--   get   start   time   for   next   step
select   @start   =   getdate()
select   count(*)   from   sales
--   write   out   record
insert   perf_tracker   (execution_id,   step_id,   start_time, end_time,
elapsed)
values   (“example”,   @exid,  2,  @start, getdate(),  datediff(ms,
@start, getdate()))
return
exec show_tracking
select * from perf_tracker

----------
537
----------
168725
execution_id step_id   start_time           end_time             elapsed
------------ --------  -------------------- --------------------- ------
1            1         Jan 4 1997  1:27PM   Jan 4 1997  1:27PM   183
1            2         Jan 4 1997  1:27PM   Jan 4 1997  1:27PM   5676

This procedure was run from the bigpubs database, where the tables are large enough to show interesting values. The output includes two rows in the perf_tracker table, and the time required to perform each step. Storing this kind of performance data in a permanent table provides a ready resource for identifying performance problems and changes in server behavior. What’s more, you can use another connection to monitor the contents of the perf_tracker table from another client connection while the procedure is still running. (This overcomes the lack of status information caused by the latency in the PRINT and RAISERROR statements.)

The module column allows several users to share the perf_tracker table. Each user can check his own results without interfering with others. It may be useful to turn on row locking for this table:

sp_tableoption perf_tracker, “insert”, true

Note the use of the ISNULL() function to handle the first row in the set. Without this function, the max() function would return null, so max()+1 would also be null. By using isnull(max()+1, 1), the first row is assigned an id of 1.

Here’s the query that shows the activity in the most recent execution set:

select *
  from perf_tracker
 where execution_id =
      (select max(execution_id)
         from perf_tracker)

execution_id step_id    start_time          end_time             elapsed
------------ ---------- ------------------- -------------------- --------
3            1          Jan 4 1997  1:41PM  Jan 4 1997  1:41PM   10
3            2          Jan 4 1997  1:41PM  Jan 4 1997  1:41PM   2230

The subquery finds the highest execution_id, which corresponds to the most recently entered set of values.