Simple process to track and log SQL Server stored procedure use

By: Aaron Bertrand | Comments (12) | Related: 1 | 2 | > Stored Procedures

Problem

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.

Solution

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:

Date/time
DatabaseID
ObjectID
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.

Custom exceptions

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.

Next Steps

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:

About the author

Aaron Bertrand (@AaronBertrand) is a passionate technologist with industry experience dating back to Classic ASP and SQL Server 6.5. He is editor-in-chief of the performance-related blog, SQLPerformance.com, and also blogs at sqlblog.org.

This author pledges the content of this article is based on professional experience and not AI generated.

View all my tips

Friday, December 28, 2018 - 2:03:43 AM - Zeeshan	Back To Top (78571)
Does it Works when we call sps from Entity framework?