There are many reasons you may want to log how long something is taking in Microsoft SQL Server.
Although there are many who think that logging should all be done in SSIS, this is something that I am willing to debate as I am not convinced that SSIS is the correct tool for all environments.
I have been working on logging how long particular things have been taking and putting it into a database. I could not find anything online and thought that this may be helpful for someone
photo credit: wwarby
Files
I have uploaded the files for this setup
This work is licensed under a Creative Commons Attribution-ShareAlike 3.0 Unported License.
Excerpts from these files are located in the explanation below.
I have released this under a creative commons license so you are free to distribute this and use it in a work environment but I request that if it has saved you time that you donate or at least keep the attribution.
Logging Overview
Logging is a necessity if you are doing something that is time critical. Many SQL programmers do not think much about how long something will take to the detriment to their users. Some things are obvious like build processes that take hours, others are less obvious such as building stored procedures to support a web application where millisecond response times are needed to be seamless to the user. Just try using something that makes you wait for a long time and you will realise why it is important to keep things moving quickly.
If someone comes to you and says that something is not performing as they expect, or you see that something appears to be running slowly you will want to log that so you can set benchmarks and compare.
This is the purpose of this script, it allows you to setup a testing category ie “Testing DW Build Time” or “Checking running multiple web stored procs” and then you can put in events ie “Build Table 1″ and “Execute name lookup”, this will track the individual events and give you consistent formatting so you can evaluate the impact of any changes you have made. It assumes that only one event is running per category at a time, but you can have as many categories as you want.
Note that if you are not testing something in a production setting you may wish to clear the cache each time before you run these.
Logging Stored Procedure in Action
Below is a sample script that demonstrates how this works.
declare @retval as int
exec @retval = dbo.spLoggingCategoryStart 'Test Category'
select @retval
exec spLoggingEventStart @retval, 'Test Event 1'
WAITFOR DELAY '00:00:10';
exec spLoggingEventStart @retval, 'Test Event 2'
WAITFOR DELAY '00:00:01';
exec spLoggingEventStart @retval, 'Test Event 3'
WAITFOR DELAY '00:00:00.1';
exec spLoggingEventStart @retval, 'Test Event 4'
WAITFOR DELAY '00:00:00.2';
exec [dbo].[spLoggingCategoryEnd] @retval
select * from EventCategories where EventCategoryKey = @retval
select * from EventLog where EventCategoryKey = @retval
This has three distinct elements, the first is where the logging starts; it declares a variable to store the ID of the event category. This is is assigned by doing
exec @retval = dbo.spLoggingCategoryStart
This needs to be run whenever you want to create a new category. Just make sure that you don’t lose track of the value by recycling the @retval variable, use a different variable for each category.
Behind the scenes this will save the category, the start time, create an event to say the category has been started.
Then you can start logging test events, all you need to do is pass the id of the category and the name of the event. For example
exec spLoggingEventStart @retval, 'Test Event 1'
This will set the previous event to be finished and create a new line for this event.
The delays are just to prove that the times are logged and that there can be different intervals.
Once you have finished with the category then you need to stop logging the category.
This can be achieved by the call
exec [dbo].[spLoggingCategoryEnd] @retval
Behind the scenes this will save the category, the end time for the category and the event, create an event to say the category has finished and calculate the duration in seconds (millisecond precision) for the category and the task.
You can see from the select statements that you can see when each started and finished and their times. If you run it multiple times you can compare and contrast.
Now all you need to do is put in real events in the script and away you go.
How It Works
Tables
There are two tables, they could be joined by foreign key but if you are using this for testing you don’t want that hassle. One stores information about the category and the other the events. The end times and calculations for durations are NULL fields so they don’t have to be populated straight away.
-- Event Categories Table
CREATE TABLE [dbo].[EventCategories](
[EventCategoryKey] [int] IDENTITY(1,1) NOT NULL,
[EventCategoryName] [varchar](50) NOT NULL,
[EventCategoryStartTime] [datetime] NOT NULL,
[EventCategoryEndTime] [datetime] NULL,
[EventCategoryDurationSec] [decimal](18, 4) NULL,
CONSTRAINT [PK_EventCategories] PRIMARY KEY CLUSTERED
(
[EventCategoryKey] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]
-- Event Log Table
CREATE TABLE [dbo].[EventLog](
[LogKey] [int] IDENTITY(1,1) NOT NULL,
[EventCategoryKey] [int] NOT NULL,
[EventName] [varchar](50) NOT NULL,
[EventStartTime] [datetime] NOT NULL,
[EventEndTime] [datetime] NULL,
[EventDurationSec] [decimal](18, 4) NULL,
CONSTRAINT [PK_EventLog] PRIMARY KEY CLUSTERED
(
[LogKey] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]
Start Category
The procedures are again rather simple.
The starting procedure looks like this
CREATE Procedure [dbo].[spLoggingCategoryStart](@EventCategoryName as varchar(50)) AS
BEGIN
-- Stored Procedure to Start Logging a Particular Category
-- This will return the Key to use for the events in this key
-- This also creates a start event for the log to make it easier to read
-- Used to see why processing is taking so long -
-- Created AB 30 Sep 2010
Declare @EventCategoryKey as int
-- Add the Values
INSERT INTO [EventCategories]
(
[EventCategoryName],
[EventCategoryStartTime]
)
VALUES
(
@EventCategoryName,
CURRENT_TIMESTAMP
)
select @EventCategoryKey = @@IDENTITY
-- Put in a Primary Start Event
select @EventCategoryName = ltrim(rtrim(left('Start: ' + @EventCategoryName, 50)))
exec spLoggingEventStart @EventCategoryKey, @EventCategoryName
RETURN @EventCategoryKey
END
This inserts the values and uses @@Identity to get the most recent value.
The times are based on Current_timestamp that gives the current time.
It makes sure the category name fits for a task and puts start in and gives the same call as you would for a new task.
Log Events
Events are logged by assuming that the category is correct (you could look it up if you like or you could use foreign keys but this was not that important to me)
It adds a new event and then grabs the id for that event. Using that ID it looks for the most recent event for that category and closes it (if it is still open).
Technically this should have been done differently, and ordered by the date as there is no guarantee an identity will be created in order but 99.9% of the time this is the case and you are saving the start times so can recover in this event.
Create Procedure [dbo].[spLoggingEventStart](@EventCategoryKey int, @EventName varchar(50)) as
BEGIN
-- Stored Procedure to Log a new event
-- This will mark the previous event for the category closed
-- This is on the premise that you can have multiple categories with their own events going at once
-- But each category can only have one event (is not mutli threaded)
-- So this will start a new entry and close the previous if it exists
-- Created 30 Sep 2010 AB
Declare @EventKey as int
-- Add the new event
INSERT INTO [EventLog]
(
[EventCategoryKey],
[EventName],
[EventStartTime]
)
values
(
@EventCategoryKey, -- <EventCategoryKey, int,>
@EventName,-- ,<EventName, varchar(50),>
CURRENT_TIMESTAMP-- ,<Event Start Time, datetime,>
)
-- Find the previous event
select @EventKey = @@IDENTITY
Set @EventKey =
(
Select
MAX(el.LogKey) EK
from
EventLog el
where
el.LogKey < @EventKey
and el.EventCategoryKey = @EventCategoryKey
)
-- Close the previous Event
update
[EventLog]
set
EventEndTime = CURRENT_TIMESTAMP
where
LogKey = @EventKey
END
Close Category
This is similar to the initial open task but in reverse. It will close the category by putting an end time in.
It will put in an ending task which serves two purposes, it closes the last task and ensures that there are values for the start and end of the category (if you choose not to put anything in the middle)
It needs to get the name of the procedure (easier in code than to hold two variables in the middle of timing)
It then calculates the times – it gets milliseconds and then divides by 1000 to get the seconds, if you used seconds you would not get that precision.
It is dividing by 1000.0 else you are doing integer division and will lose the end times.
CREATE Procedure [dbo].[spLoggingCategoryEnd](@EventCategoryKey as int) AS
BEGIN
-- Stored Procedure to End Logging a Particular Category
-- This will close off any open tasks
-- Will insert a Final task
-- Will calculate duration for the events and for the overall category
-- Created AB 30 Sep 2010
-- Get the Category Name
Declare @EventCategoryName as varchar(50)
Set @EventCategoryName = (Select top 1 ec.EventCategoryName From EventCategories ec where ec.EventCategoryKey = @EventCategoryKey)
-- Put in a Finish Event
select @EventCategoryName = ltrim(rtrim(left('Final: ' + @EventCategoryName, 50)))
-- Put in last event for category (should close previous one)
exec spLoggingEventStart @EventCategoryKey, @EventCategoryName
-- Finish off all unclosed events
update
[EventLog]
set
EventEndTime = CURRENT_TIMESTAMP
where
EventEndTime is null
and EventCategoryKey = @EventCategoryKey
-- Calculate Times for All Events for the Category
update
[EventLog]
set
EventDurationSec = DATEDIFF(millisecond, EventStartTime, EventEndTime) / 1000.0
where
EventCategoryKey = @EventCategoryKey
-- Insert End time for the Category in the Category Table
update
[EventCategories]
set
[EventCategoryEndTime] = CURRENT_TIMESTAMP,
EventCategoryDurationSec = DATEDIFF(millisecond, EventCategoryStartTime, CURRENT_TIMESTAMP) / 1000.0
where
@EventCategoryKey = EventCategoryKey
END
Conclusion
I think this is quite useful as it is easy to implement and is useful to have the scripts in a bookmark so you can put them in when you see the need.
If you have any alternatives or ways to improve or just want to discuss general SQL issues please contact me or leave a comment.
Watching a documentary in the background when doing an assignment, I heard about the French Foreign Legion. They supposedly have 12 times more applicants than positions. They are elite and don’t ask questions just hard work and loyalty.
Oct
08
Request for Comments
by Andrew
The terabell blog used to be updated regularly. I gave up when went on my honeymoon and never got back into it. The reason that I gave up was that I did not think anyone was reading it and since I knew my positions on various topics I did not feel I was gaining a lot by shouting my knowledge into what felt like an empty room.
I have recently started again because I wanted to use this blog akin to a diary for personal reference and to be a searchable archive of technological issues and debating positions so I could see how I have changed as time has gone by.
The reason that I did not think that anyone was reading is because there never were any comments on the site. I never was emailed and no one questioned what I was saying. It is only this week after getting at least 50 emails about people unsubscribing from the email feeds from the blog did I realise that there were subscribers. It appears that there were over 200 however that is shrinking, implying not only were people reading but they liked it enough to subscribe. Searching online there were even posts about people who read the blog before its reinvention (its pretty much the same but looks different and my old server corrupted so I don’t have the old posts as an archive).
I am therefore asking if you are reading this blog or are interested in learning more about something (or hearing less about it) please drop me a comment or an email and let me know.
So please let me know what you think of the site, what is happening, where you are from and help me feel a little less crazy.
Hope you have a good day
photo credit: SpecialKRB
Tags: blog, comments, community
3 comments