By: Aaron Bertrand | Updated: 2010-05-10 | Comments (12) | Stored Procedures
In many environments there is a lack of consistent logging from stored procedures - if there is any logging at all. In general, we tend to leave it up to the application to record any errors, but in systems with many different applications, it can be tedious to collect exception information and figure out which stored procedures are having issues. And more generically, it is difficult to determine which stored procedures are being used at all, without running a server-side trace for a significant amount of time.
By creating a central logging system, you can add both error and general usage logging to stored procedures with minimal intrusion. On my systems I create a separate database called Utility which contains general purpose and system-wide items like this. So if you don't have a generic database for this type of purpose, you can create one:
CREATE DATABASE Utility; GO
Now, what kind of things would you be interested in logging from your stored procedures? For a starting list:
- Fully-qualified procedure name
- Line number
- Error message
- Any additional info you want to pass
Why both DatabaseID + ObjectID and fully qualified procedure name? Because procedures can be dropped and re-created, dropped entirely, or re-named. I usually add the extra column for additional info in case there is other context I want to pass and log (for example, if I am using RAISERROR manually), even if in most cases the value will be NULL.
So here is the DDL for the table you can create to capture these things:
USE Utility; GO CREATE TABLE dbo.ProcedureLog ( LogDate SMALLDATETIME NOT NULL DEFAULT CURRENT_TIMESTAMP, DatabaseID INT, ObjectID INT, ProcedureName NVARCHAR(400), ErrorLine INT, ErrorMessage NVARCHAR(MAX), AdditionalInfo NVARCHAR(MAX) ); GO CREATE CLUSTERED INDEX cx_LogDate ON dbo.ProcedureLog(LogDate); GO
I put the clustered index on LogDate to ensure that rows are always being added monotonically, and to allow me to purge older data over time with minimal interruption to current activity. Depending on how you are going to query the data, you may want additional indexes on other columns (or a different indexing strategy altogether).
Now, how can you populate this table? Well, in order to minimize the amount of code you'll need to call in each stored procedure in your user database(s), you'll want to create a stored procedure in each database (this will allow you to grab context to DB_ID() without having to use a local variable in each procedure). You can create this procedure in model as well, so that it will automatically be created in new databases. In my environments I put these procedures in a separate schema, both for logical separation, and so that they bubble to the bottom of the stored procedures list in Object Explorer:
USE <UserDatabase>; GO CREATE SCHEMA utility AUTHORIZATION dbo; GO CREATE PROCEDURE utility.Log_ProcedureCall @ObjectID INT, @DatabaseID INT = NULL, @AdditionalInfo NVARCHAR(MAX) = NULL AS BEGIN SET NOCOUNT ON; DECLARE @ProcedureName NVARCHAR(400); SELECT @DatabaseID = COALESCE(@DatabaseID, DB_ID()), @ProcedureName = COALESCE ( QUOTENAME(DB_NAME(@DatabaseID)) + '.' + QUOTENAME(OBJECT_SCHEMA_NAME(@ObjectID, @DatabaseID)) + '.' + QUOTENAME(OBJECT_NAME(@ObjectID, @DatabaseID)), ERROR_PROCEDURE() ); INSERT Utility.dbo.ProcedureLog ( DatabaseID, ObjectID, ProcedureName, ErrorLine, ErrorMessage, AdditionalInfo ) SELECT @DatabaseID, @ObjectID, @ProcedureName, ERROR_LINE(), ERROR_MESSAGE(), @AdditionalInfo; END GO
Now that you are in your user database, it is very easy to log events from your stored procedures. Let's look at four scenarios:
Existing CATCH handlers
It is easy to supplement the CATCH handler(s) in existing stored procedures to also log to your central table. Let's say you have a procedure like this:
CREATE PROCEDURE dbo.CauseError AS BEGIN SET NOCOUNT ON; BEGIN TRY SELECT 1/0; END TRY BEGIN CATCH RAISERROR('You tried to divide by 0.', 0, 1); END CATCH END GO
Logging this error becomes a trivial, one-line addition:
ALTER PROCEDURE dbo.CauseError AS BEGIN SET NOCOUNT ON; BEGIN TRY SELECT 1/0; END TRY BEGIN CATCH EXEC utility.Log_ProcedureCall @ObjectID = @@PROCID; RAISERROR('You tried to divide by 0.', 0, 1); END CATCH END GO
If you call this procedure a few times, you will see rows start to populate in the ProcedureLog table in the Utility database.
You can perform similar logging in cases where you are currently raising your own exceptions, for example in the case of a duplicate check:
CREATE PROCEDURE dbo.RaiseError @Name NVARCHAR(64) AS BEGIN SET NOCOUNT ON; IF EXISTS (SELECT 1 FROM sys.objects WHERE name = @Name) BEGIN DECLARE @msg NVARCHAR(MAX); SET @msg = 'Something went horribly wrong.'; RAISERROR(@msg, 11, 1); RETURN; END END GO
Again, adding this event to the logging table requires a simple addition (and also allows you to pass your custom message):
ALTER PROCEDURE dbo.RaiseError @Name NVARCHAR(64) AS BEGIN SET NOCOUNT ON; IF EXISTS (SELECT 1 FROM sys.objects WHERE name = @Name) BEGIN DECLARE @msg NVARCHAR(MAX); SET @msg = 'Something went horribly wrong.'; EXEC utility.Log_ProcedureCall @ObjectID = @@PROCID, @AdditionalInfo = @msg; RAISERROR(@msg, 11, 1); RETURN; END END GO
General usage logging
Of course you do not need to only log errors; you can simply log that a procedure has been called, in which case the error-related columns will be NULL. This can be useful if you want to keep track of which stored procedures are getting called most frequently, and which are not getting called at all. In this case you simply need to add a call to the end of the stored procedure, without worring about CATCH or RAISERROR:
CREATE PROCEDURE dbo.LogCallNoError AS BEGIN SET NOCOUNT ON; /* do stuff */ EXEC utility.Log_ProcedureCall @ObjectID = @@PROCID; END GO
In fact, you could edit the "New Stored Procedure" template to automatically insert this line every time you create a new stored procedure using the template - that doesn't help inject in into existing procedures but will help ensure that new procedures do perform logging.
- Note: for the general usage logging case, you can, of course, use a new DMV introduced in SQL Server 2008, sys.dm_exec_procedure_stats. The problem with this DMV is that, like most DMVs, it does not persist its data across restarts of SQL Server (including cluster failover events) - so the information will not always be complete. With a central logging table, you can dictate how long you want to hold on to certain information.
Observing unused procedures
Once you have added the error logging throughout your stored procedures and have significant usage history (at least one full business cycle), you can then determine which stored procedures are not being used in the current database, by running the following query:
SELECT QUOTENAME(OBJECT_SCHEMA_NAME(p.[object_id])) + '.' + QUOTENAME(OBJECT_NAME(p.[object_id])) FROM sys.procedures AS p LEFT OUTER JOIN Utility.dbo.ProcedureLog AS l ON p.[object_id] = l.ObjectID AND l.DatabaseID = DB_ID() WHERE OBJECT_DEFINITION(p.[object_id]) LIKE '%utility.Log_ProcedureCall%' AND p.[object_id] <> OBJECT_ID('utility.Log_ProcedureCall') AND l.ObjectID IS NULL AND l.LogDate < ;
Note that the WHERE clause restricting LogDate to rows older than today is there to avoid interfering with current activity. If you have a very heavily-used system, you may want to rely on a backup of the Utility database that is restored elsewhere periodically, or at least use SNAPSHOT isolation when performing this kind of research.
You could of course add other things to this logging mechanism. For example, if you wanted to log the user name, host name, application name and even IP address of the caller, you could grab all of those values within the logging procedure simply by using @@SPID and looking at the DMVs sys.dm_exec_sessions and sys.dm_exec_connections. You can also add performance metrics, such as duration, by defining a variable at the beginning of your procedures and logging the activity at the end (including the delta). I'll leave some of these more advanced ideas for a future tip; just keep in mind that everything you log costs something, either in performance, storage, or both.
- Create a database that you can use to store central logging data.
- Create a table to log stored procedure activity.
- Create a procedure in each user database that logs to the central table.
- Gradually add a call to this logging procedure to the rest of your stored procedures.
- Review the following tips and Books Online topics:
Last Updated: 2010-05-10
About the author
View all my tips