Database - SQL Server - Logging

I would like to talk about stored procedure logging today. Many DBAs or database developers always have a so called "logging framework" in their applications. I would like to share my "logging framework" in this blog. I hope you guys can provide some thought to make it more robust.

To me, logging and audit trail should be separated. So, I try not to store who and when someone ran a stored procedure in my application.

What do we log?
1. Execution time
    a. start and end execution time of a stored procedure
    b. start and end execution time of a step in a stored procedure
2. Error
    a. catch and store error information for troubleshooting later

Why do we log?
1. Enable us to identify slow running stored procedures
2. Give us some hints to take proactive actions before a stored procedure screws up our application/database/server
3. Resolve errors that occurred during run-time (improve application quality by removing possible flaw in the stored procedure)

When do we log?
IMO, we don't log all stored procedures. So, I would log stored procedures that only involve operations below:
1. ETL stored procedure
2. Report stored procedure
3. Stored procedures that contain complex business logic
For those stored procedures that need to be executed FAST and required to support very high concurrency, I don't recommend to add logging to the stored procedure. Each byte that we use for disk IO access is very important. For the same reason, each variable that we declare in the stored procedure does consume memory. Well, we shouldn't discuss about potential performance issues in this blog.

My requirements of logging
1. Able to be turned on/off at stored procedure level
2. Able to store the log information in table or output the log information on screen immediately
3. Able to maintain the link between execution step info and error message
4. Fast - only sequential INSERTs (perhaps minimum UPDATE is acceptable)
5. Log data is easy to analyze

Open for discussion
1. Do you prefer storing logging tables on separate data files?
2. Would you centralize all logging in a dedicated database/server?

Any comment is most welcome. :)

Codes:
IF NOT EXISTS(SELECT 1 FROM sys.schemas WHERE name='ERROR')

EXECUTE ('CREATE SCHEMA ERROR')
GO
IF OBJECT_ID('ERROR.error') IS NOT NULL
DROP TABLE ERROR.error
GO
CREATE TABLE ERROR.error(
ErrorDateTime  SMALLDATETIME  NOT NULL CONSTRAINT DF_ErrorDateTime DEFAULT GETUTCDATE(),
ErrorNumber    INT NOT NULL,
ErrorSeverity  INT NOT NULL,
ErrorState     INT NOT NULL,
ErrorLine      INT NOT NULL,
traceSummaryID INT NOT NULL,
ErrorProcedure NVARCHAR(126)  NOT NULL CONSTRAINT DF_ErrorProcedure DEFAULT '',
ErrorMessage   NVARCHAR(2048) NOT NULL CONSTRAINT DF_ErrorMessage DEFAULT ''
)
GO
IF OBJECT_ID('ERROR.INS_error') IS NOT NULL
DROP PROCEDURE ERROR.INS_error
GO
CREATE PROCEDURE ERROR.INS_error
@iTraceSummaryID INT,
@iPrintOnScreen  BIT=0 --developer wants to see the output on screen only
AS
BEGIN
SET NOCOUNT ON;
IF @iPrintOnScreen=1
   PRINT 'Err '+CONVERT(VARCHAR,ERROR_NUMBER())+',Severity '+CONVERT(VARCHAR,ERROR_SEVERITY())+', State '+CONVERT(VARCHAR,ERROR_STATE())+', Line '+CONVERT(VARCHAR,ERROR_LINE())+' - '+ERROR_MESSAGE()
ELSE
INSERT INTO ERROR.error(ErrorNumber,ErrorSeverity,ErrorState,ErrorProcedure,ErrorLine,ErrorMessage,traceSummaryID)
SELECT 
ISNULL(ERROR_NUMBER(),0) AS ErrorNumber
,ISNULL(ERROR_SEVERITY(),0) AS ErrorSeverity
,ISNULL(ERROR_STATE(),0) AS ErrorState
,ISNULL(ERROR_PROCEDURE(),'') AS ErrorProcedure
,ISNULL(ERROR_LINE(),0) AS ErrorLine
,ISNULL(ERROR_MESSAGE(),'') AS ErrorMessage
,ISNULL(@iTraceSummaryID,0) AS traceSummaryID;
END
GO
IF NOT EXISTS(SELECT 1 FROM sys.schemas WHERE name='CONFIG')
EXECUTE ('CREATE SCHEMA CONFIG')
GO
IF OBJECT_ID('CONFIG.procReturnCode') IS NOT NULL
DROP TABLE CONFIG.procReturnCode
GO
-- List of Return Codes that must be same across all environments
CREATE TABLE CONFIG.procReturnCode(
procReturnCodeID TINYINT NOT NULL,
name             NVARCHAR(120) NOT NULL
)
GO
INSERT INTO CONFIG.procReturnCode(procReturnCodeID,name)
SELECT 0,'OK' UNION ALL
SELECT 10,'Error-Schema' UNION ALL
SELECT 30,'Error-Business Logic'   UNION ALL
SELECT 100,'Error-Data Validation' UNION ALL
SELECT 240,'Error-Others';
GO
IF NOT EXISTS(SELECT 1 FROM sys.schemas WHERE name='LOGGING')
EXECUTE ('CREATE SCHEMA LOGGING')
GO
IF OBJECT_ID('LOGGING.traceSummary') IS NOT NULL
DROP TABLE LOGGING.traceSummary
GO
CREATE TABLE LOGGING.traceSummary(
traceSummaryID INT IDENTITY(-2147483648,1) CONSTRAINT PK_traceSummary PRIMARY KEY,
procName       NVARCHAR(261) NOT NULL
)
GO
IF OBJECT_ID('LOGGING.traceDetail') IS NOT NULL
DROP TABLE LOGGING.traceDetail
GO
CREATE TABLE LOGGING.traceDetail(
traceSummaryID INT NOT NULL,
step           TINYINT  NOT NULL CONSTRAINT DF_traceDetail_step DEFAULT 0,
traceDateTime  DATETIME NOT NULL CONSTRAINT DF_traceDetail_traceDateTime DEFAULT GETUTCDATE(),
stepName       NVARCHAR(128) NOT NULL CONSTRAINT DF_traceDetail_stepName DEFAULT ''
)
GO
CREATE NONCLUSTERED INDEX IDX_LOGGING_traceDetail_1 ON LOGGING.traceDetail(traceSummaryID) INCLUDE(step)
GO
IF OBJECT_ID('LOGGING.INS_trace') IS NOT NULL
DROP PROCEDURE LOGGING.INS_trace
GO
CREATE PROCEDURE LOGGING.INS_trace
@iTraceSummaryID INT,
@iProcName       NVARCHAR(261),
@iStepName       NVARCHAR(128)='', --optional, for developer to mark a step only
@iPrintOnScreen  BIT=0             --developer wants to see the output on screen only
AS
BEGIN
IF @iPrintOnScreen=1
BEGIN
PRINT  CONVERT(VARCHAR,GETUTCDATE(),121)+'-'+@iStepName
RETURN @iTraceSummaryID
END
IF @iTraceSummaryID=0
BEGIN
INSERT INTO LOGGING.traceSummary(procName) VALUES (@iProcName);
SET @iTraceSummaryID=SCOPE_IDENTITY();
END
INSERT INTO LOGGING.traceDetail(traceSummaryID,stepName,step)
SELECT @iTraceSummaryID,@iStepName
,(SELECT ISNULL(MAX(step),0)+1 FROM LOGGING.traceDetail WITH(NOLOCK) WHERE traceSummaryID=@iTraceSummaryID)

RETURN @iTraceSummaryID
END
GO
IF OBJECT_ID('dbo.template_Transaction') IS NOT NULL
DROP PROCEDURE dbo.template_Transaction
GO
CREATE PROCEDURE dbo.template_Transaction
@iParam INT,
@oParam INT OUTPUT
AS
BEGIN TRY
SET NOCOUNT ON;
-- ********************************************************************************************* //
-- Local Variables & Initialization
DECLARE @returnCode TINYINT=0
DECLARE @traceSummaryID INT=0
DECLARE @printOnScreen  BIT=0
DECLARE @proc NVARCHAR(261)=QUOTENAME(OBJECT_SCHEMA_NAME(@@PROCID))+'.'+QUOTENAME(OBJECT_NAME(@@PROCID))

-- Logging
EXECUTE @traceSummaryID=LOGGING.INS_trace @traceSummaryID,@proc,'Start',@printOnScreen
-- ********************************************************************************************* //
-- Temporary Tables
-- CREATE TABLE #t(ID INT)
-- DECLARE @t AS TABLE(ID INT)
EXECUTE @traceSummaryID=LOGGING.INS_trace @traceSummaryID,@proc,'Temporary Table',@printOnScreen
-- Business Logic goes here

-- NOTE: Avoid calling LOGGING.INS_trace in the TRANSACTION!
--       1. reduce LOCK on trace tables
--       2. when rolled-back, everything is gone
--       Keep transaction small
BEGIN TRANSACTION


END_OF_SP:
COMMIT
-- Logging
EXECUTE @traceSummaryID=LOGGING.INS_trace @traceSummaryID,@proc,'End',@printOnScreen
END TRY
BEGIN CATCH
IF XACT_STATE()= 1 COMMIT
IF XACT_STATE()=-1 ROLLBACK
-- execute everything else after COMMIT/ROLLBACK
EXECUTE ERROR.INS_error @traceSummaryID,@printOnScreen --establish a link between logging and error handling
RETURN  @returnCode -- refer CONFIG.procReturnCode
END CATCH
GO