SQLServer : Timing Batch Jobs

by bitznbitez

DBA’s know that sometimes getting developers to actually tracking times and durations of jobs is like pulling teeth.  Especially if you want to have all the timings in a central location.   Here is one solution, which makes life easy on the developers.   This will only work for batch jobs, where durations are measured in minutes and hours, it has to much overhead for tracking things in the second or subsecond ranges.

I use a database named Monitoring to track everything.   It doesn’t matter what database on the server this can be added to their T-SQL and Stored Procedures etc.

First the table DDL

CREATE TABLE [dbo].[Timings](
	[Id] [bigint] IDENTITY(1,1) NOT NULL,
	[Label] [varchar](255) NOT NULL,
	[Detail] [varchar](255) NOT NULL,
	[StartTime] [datetime] NULL,
	[StopTime] [datetime] NULL,
	[CompletionStatus] [char](1) NULL,
	[Duration] [int] NULL,
    PRIMARY KEY CLUSTERED (	[Id] ASC )
) ;

ALTER TABLE [dbo].[Timings] ADD  CONSTRAINT [DF_Timings_Detail]  
  DEFAULT ('') FOR [Detail];
ALTER TABLE [dbo].[Timings] ADD  CONSTRAINT [DF_Timings_StartTime]  
  DEFAULT (getdate()) FOR [StartTime];
ALTER TABLE [dbo].[Timings] ADD  CONSTRAINT [DF_Timings_CompletionStatus]  
  DEFAULT ('R') FOR [CompletionStatus];

Next the Procedure DDL

create procedure startTiming
  @TimingLabel varchar(256),
  @TimingDetail varchar(255) = ''
as
begin
    
	declare @lastId bigint;

	insert into [Monitoring].[dbo].[Timings] ( [Label], [Detail] ) 
          values ( @TimingLabel, @TimingDetail );

	select @lastId = scope_identity();

	return @lastId;

end
go

create procedure stopTiming
  @TimingId bigint,
  @CompletionStatus char(1) = 'C'
as
begin

    update [Monitoring].[dbo].[Timings] 
	set [Timings].[StopTime] = current_timestamp
          , [CompletionStatus] = @CompletionStatus
          , [Timings].[Duration] = DATEDIFF(SECOND,[StartTime]
          , CURRENT_TIMESTAMP)
	where [Timings].[Id] = @TimingId;

end
go

Finally sample usage


declare @myId bigint;

-- Specify a step used to process different states
-- This time for TX
-- Any step specific detail can e used in the 2nd optional field

exec @myId = startTiming 'Test 1', 'TX' ;
select * from [Monitoring].[dbo].[Timings];
waitfor delay '00:00:05'
exec stopTiming @myId;

-- A Simpler invocation
exec @myId = startTiming 'Test 2' ;
waitfor delay '00:00:05'
exec stopTiming @myId;

-- Simple invocation indicating a failed completion
-- Instead of default successful completion

exec @myId = startTiming 'Test 2' ;
waitfor delay '00:00:05'
exec stopTiming @myId, 'F';

select * from [Monitoring].[dbo].[Timings];

Followed by output



(1 row(s) affected)
Id                   Label         Detail      StartTime               StopTime                CompletionStatus Duration
-------------------- ------------- ----------- ----------------------- ----------------------- ---------------- -----------
1                    Test 1        TX          2013-06-06 15:38:23.990 NULL                    R                NULL

(1 row(s) affected)

(1 row(s) affected)


(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)
Id                   Label         Detail      StartTime               StopTime                CompletionStatus Duration
-------------------- ------------- ----------- ----------------------- ----------------------- ---------------- -----------
1                    Test 1        TX          2013-06-06 15:38:23.990 2013-06-06 15:38:29.093 C                6
2                    Test 2                    2013-06-06 15:38:29.097 2013-06-06 15:38:34.100 C                5
3                    Test 2                    2013-06-06 15:38:34.100 2013-06-06 15:38:39.100 F                5

(3 row(s) affected)

There are many ways to do this, you can probably come up with a better way.

Advertisements