Stored Procedure Logging

Thu Sep 21, 2006 by Brett Kaiser (x002548) in sql-server

Every so often, someone asks, "How do I know who executed a SQL Statement against my database".

Well you can either have SQL Profiler running all the time (which can be very expensive), or you can use Lumingent's Log Explorer.

I have taken a different tack lately.

Any Access to a database I am supporting will be done ONLY Through stored procedures. OK, that's not "lately", but the part I've added is that the developers MUST call the sproc below. What this does is to log every stored procedure call. I now have statistics as to what's being called when, and how long the operation takes. There are several benefits, but the best being that I can see which developers don't have their thinking cap on in dev, and we can proactiveley review these sprocs.

OK, now you say, how do you know that developer is callin the logging sproc, and the short answer is, that in dev, I don't. However, No sprocs get moved to QA without a reivew by me or someone on the DBA team. Once it's in QA, they can't touch the code. After QA Sign off, the that code gets moved to UAT, then up to PROD.

In any case I find it useful, and the execution of the logging is in the microseconds. I guess the downside of a app that gets slammed with millions of hits is that this could add up and affect performance, but shy of that, we have not noticed any impact. In any case, for what it's worth here's the sproc and the table DDL. One other note, I do this on other platforms as well, for example DB2 OS/390...only problem there is the need to monitor the tablespace for this table, since you coul blow out on extents...which is not really a problem on SQL Server...except that you potentially could run out of disk space...In either case, you need to monitor that, and archive the data. Any comments are appreciated.

if exists (select * from dbo.sysobjects where id = object_id(N'[dbo].[usp_LogProcCalls]') and OBJECTPROPERTY(id, N'IsProcedure') = 1)
drop procedure [dbo].[usp_LogProcCalls]
GO

SET QUOTED_IDENTIFIER OFF
GO
SET ANSI_NULLS ON
GO

CREATE PROCEDURE [dbo].[usp_LogProcCalls] (
   @SprocName sysname
, @TranStart datetime
, @TranEnd datetime
, @Rows int
, @Err   int
, @Paramters varchar(255)
, @rc   int OUTPUT)
AS
SET NOCOUNT ON

Declare @error int, @RowCount int, @Error_Message varchar(255), @Error_Type int, @Error_Loc int

BEGIN TRAN
DECLARE @LogStart datetime
SELECT @rc = 0, @LogStart = GetDate()
IF (SELECT @@TRANCOUNT) <> 1
   BEGIN
    SELECT @Error_Loc = 1
         , @Error_Message = 'The logging procedure must be executed outside of any transaction. @@TRANSCOUNT='
   + CONVERT(varchar(5),@@TRANCOUNT)
         , @Error_Type = 50002, @rc = -6661
    GOTO usp_LogProcCalls_Error
   END

INSERT INTO Sproc_Log (
[SprocName]
, [TranStart]
, [TranEnd]
, [LogStart]
, [LogEnd]
, [Rows]
, [Err]
, [Paramters])
SELECT
@SprocName
, @TranStart
, @TranEnd
, @LogStart
, GetDate()
, @Rows
, @Err
, @Paramters

Select @RowCount = @@ROWCOUNT, @error = @@error

IF @error <> 0
   BEGIN
    SELECT @Error_Loc = 2, @Error_Type = 50001, @rc = -6662
    GOTO usp_LogProcCalls_Error
   END

IF @RowCount <> 1
   BEGIN
    SELECT @Error_Loc = 3
         , @Error_Message = 'Expected 1 row to be inserted in to the sproc log. Actual Number inserted = '
   + CONVERT(varchar(5),@RowCount)
         , @Error_Type = 50002, @rc = -6663
    GOTO usp_LogProcCalls_Error
   END

COMMIT TRAN

usp_LogProcCalls_Exit:

RETURN

usp_LogProcCalls_Error:

Rollback TRAN

If @Error_Type = 50001
BEGIN

Select @error_message = (Select 'Location: ' + ',"' + RTrim(Convert(char(3),@Error_Loc))
          + ',"' + ' @@ERROR: ' + ',"' + RTrim(Convert(char(6),error))
          + ',"' + ' Severity: ' + ',"' + RTrim(Convert(char(3),severity))
          From master..sysmessages
        Where error = @error)
END

If @Error_Type = 50002

BEGIN
Select @Error_Message = 'Location: ' + ',"' + RTrim(Convert(char(3),@Error_Loc))
+ ',"' + ' Severity: UserLevel '
+ ',"' + ' Message: ' + ',"' + RTrim(@Error_Message)
END

RAISERROR @Error_Type @Error_Message

GOTO usp_LogProcCalls_Exit
GO
SET QUOTED_IDENTIFIER OFF
GO
SET ANSI_NULLS ON
GO

if exists (select * from dbo.sysobjects where id = object_id(N'[dbo].[Sproc_Log]') and OBJECTPROPERTY(id, N'IsUserTable') = 1)
drop table [dbo].[Sproc_Log]
GO

CREATE TABLE [dbo].[Sproc_Log] (
[SprocName] [sysname] NOT NULL ,
[TranStart] [datetime] NOT NULL ,
[TranEnd] [datetime] NOT NULL ,
[SYSTEM_USER] [char] (30) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
[LogStart] [datetime] NOT NULL ,
[LogEnd] [datetime] NOT NULL ,
[Rows] [int] NOT NULL ,
[Err] [int] NOT NULL ,
[Paramters] [varchar] (255) COLLATE SQL_Latin1_General_CP1_CI_AS NULL
) ON [PRIMARY]
GO

Legacy Comments


Tom Hamilton 2006-09-25	re: Stored Procedure Logging I like this idea very much but hit an error when compiling the sProc: Msg 137, Level 15, State 1, Procedure usp_LogProcCalls, Line 78 Must declare the scalar variable "@error_message".

2006-09-25	re: Stored Procedure Logging Case ! Change @error_message to @Error_Message fixes problem

Brett 2006-09-26	re: Stored Procedure Logging Sorry, my databases are never set up to be Case Sensitive...I mean, what's the point

pankaj 2006-12-04	re: Stored Procedure Logging how do call a stored procedure with out parameters. i.e Procedure proeno (Peno IN Number, PEname IN Varchar2, Sal OUT Number) AS Leno number(7); LEname varchar2(10); Lsal Number(10,2); Begin select eno,ename,sal into Leno,LEname,Lsal from emp where eno = peno; end; to execute this i have 2 pass values . & wat shud the out parameter values shud be.