Learn more about SQL Server tools

mssqltips logo
 

Tutorials          DBA          Dev          BI          Career          Categories          Webcasts          Whitepapers          Today's Tip          Join

Tutorials      DBA      Dev      BI      Categories      Webcasts

DBA    Dev    BI    Categories

Next Webcast - The Cloud won't fix that (click for more info)
 

Simple process to track and log SQL Server stored procedure use


By:   |   Read Comments (11)   |   Related Tips: 1 | 2 | More > 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


Last Update:


next webcast button


next tip button



About the author
MSSQLTips author Aaron Bertrand Aaron Bertrand (@AaronBertrand) is a Product Manager at SentryOne, 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 serves as a community moderator for the Database Administrators Stack Exchange.

View all my tips





Post a comment or let the author know this tip helped.

All comments are reviewed, so stay on subject or we may delete your comment. Note: your email address is not published. Required fields are marked with an asterisk (*).

*Name    *Email    Email me updates 


Signup for our newsletter
 I agree by submitting my data to receive communications, account updates and/or special offers about SQL Server from MSSQLTips and/or its Sponsors. I have read the privacy statement and understand I may unsubscribe at any time.



    



Friday, March 16, 2018 - 3:41:39 PM - Pete Back To Top

 Excellent, works like a charm, thank you!!

 


Friday, January 05, 2018 - 10:12:38 AM - Travis Back To Top

 @Aaron,

 

I created the table and procedure now what do i need to do if i am simply looking to log stored procedure usages (calls)

What do i need to add to existing procedures so that they populate the table?

 

Relatively new. take it easy on me lol.

 


Thursday, May 05, 2016 - 3:43:00 PM - Greg Martin Back To Top

Hi - thanks for the tutorial. One question:

I put the clustered index on LogDate to ensure that rows are always being added monotonically

 

What does being added monotonically mean and why is it good?


Monday, January 04, 2016 - 12:54:14 PM - Mageddo Back To Top

 @Aaron,

That is exactly the solution that I'm trying to avoid - having to declare a variable.  One more "moving part" that needs to be set by the developer just to log. 

I was hoping that perhaps there was some global variable - like @@procid or @@servername or some way of deriving the db from some other variable or system context (it is really funny that MS has the server name global and the lower level proc id global, but not the database that sits in between).

But, thank you - at least you've confirmed that a one-line logger statement isn't going to happen using a database id.


Monday, January 04, 2016 - 9:43:24 AM - Aaron Bertrand Back To Top

Mageddo, the problem is not that you can't pass database id to a stored procedure, it is that functions can't be arguments. You also can't say @param = SCOPE_IDENTITY() or @param = GETDATE(). Try this form instead, where you simply define a local variable first:

    DECLARE @DBID INT = DB_ID();

    EXEC dbo.procedure_name @database_id = @DBID;


Thursday, December 31, 2015 - 10:58:08 AM - Mageddo Back To Top

I'm trying to implement a logger like you have.   It is central and in a utility database.

Howver, db_id() cannot be passed to a proc, unlike @@procid , which can.  (Stupid MS, just stupid.)

So, how are you are passing in the db_id() to your logger proc?  I don't see it, and thus it wuold seem to me that this logger is only useful for stuff in the utility database itself, but nothing more as the db_id() is required to resolve the object name passed by @@procid.

Or, have I missed something?


Thursday, March 27, 2014 - 9:10:48 AM - Aaron Bertrand Back To Top

Hi Swagat,

Is it possible you have a cycle (e.g. A calls B, B calls C, C calls A)? I couldn't reproduce the scenario. You'll have to post the stored procedure definitions somewhere or e-mail them to me at abertrand AT sqlsentry DOT net and I'll be happy to have a look.


Thursday, March 27, 2014 - 8:29:29 AM - Swagat Back To Top

I have tried this solution. When i call the log procedure from the top proc and also within the nested procs i get nesting errors. Wondder why?

 

ProcA->Log_ProcedureCall

ProcA->ProcB

            ProcB->Log_ProcedureCall

            ProcA->ProcC

                       ProcC->Log_ProcedureCall

This is the scenario which causes:-

SQL Error: Maximum stored procedure, function, trigger, or view nesting level exceeded (limit 32)

 

But, many thanks for this , but for now,  im direcly inserting into the log table and not calling the Log_ProcedureCall.


Tuesday, August 23, 2011 - 4:41:13 AM - Usman Butt Back To Top

Hi Aaron,

Its always nice to read your tips and blogs. Just wandering catching the input parameters passed to the procedure could be very very useful (e.g. which input parameter/s yield more execution time OR bad execution plan). So keeping SQL 2005 in perspective, what would be the best way to get those parameters? One instant solution came to mind was to concatenate the parameters as a String and pass it to Utility procedure. But I would definitely want you to put some light on this. Thanks.

With best regards,


Wednesday, February 23, 2011 - 4:48:51 PM - Aaron Bertrand Back To Top

Hi afarago,

Yes, it is true that an outer transaction will roll back the write to the log.  There are ways around this, of course:

(a) build the logging into the middle layer or directly into your application. The app/method can then performing any logging activities *after* the rollback - just like you would in a catch handler directly in T-SQL (using a table variable, which survives a rollback, to hold intermediate results if necessary).

(b) don't let the app control transaction state (in my environments I've been able to enforce that transaction state is the responsibility of the database, especially when multiple apps are involved, since each developer might implement something differently). Easier said than done, but if you're designing now, consider not controlling transactions in the app.

(c) use CLR, xp_cmdshell, loopback linked server, etc. to log - these will be unaffected by rollback.

(d) see Simon Sabin's solution using event notifications and trace events: http://sqlblogcasts.com/blogs/simons/archive/2010/10/17/logging-messages-during-a-transaction.aspx

If you are just after frequency of procedure calls and not necessarily parameter or error information, starting with SQL Server 2008 look at sys.dm_exec_procedure_stats.

Obviously, this is a strong case for autonomous transactions in SQL Server. Please vote for these items about autonomous / nested transactions:

http://connect.microsoft.com/SQLServer/feedback/details/296870/add-support-for-autonomous-transactions

http://connect.microsoft.com/SQLServer/feedback/details/324569/add-support-for-true-nested-transactions


Wednesday, February 23, 2011 - 5:18:22 AM - afarago Back To Top

What will happen when the application calling your SP rolls back the transaction?

 


Learn more about SQL Server tools