Sql-server – Stored Procedure Processing and Error Log

Architectureauditloggingsql server 2014stored-procedures

I used to work for a company where they had this 3rd party Data warehouse Solution. Obviously all the objects and tables were hidden in the Supporting database so I don't have clear idea on what exactly happened inside some of the stored procedure. I saw this interesting stored procedure there and want to replicate that in my own solution but I just can't get my head around on how it works. I am describing the stored procedure below and it will be really helpful if someone can give me some ideas on how to achieve this. Even better if you can suggest me how I can make this even better.

Stored procedure was called process log. It had Parameters like DBID, ObjectId, Step, Status, Remarks, Reads, Inserts, Updates, Deletes

What we had to do was, inside every stored procedure, we have to execute this stored procedure with Status as 2 (In Progress) During the process where can execute this stored procedure multiple time at the end of each step or section after increasing the value of variable step. based on the row counts of Insert update select and delete statements we were supposed to record values in respective stored procedure parameter variables.
In the end you can execute same stored procedure with Status of 3 (Completed) or if the procedure ended up in catch block, status will be 4 (Failed) in the remarks section we can copy SQL's error messages.

To see all this information, we were given access to a Report, For which obviously I didn't have the source code but the report showed what time stored procedure started when it finished, what was the status how many inserts updates deletes and reads it did. if it failed, what was the error message?

I already have few ideas for improvements to store, who started it?, what were the values of parameters? For who started the stored procedure part, I have a confusion. Most of these stored procedure run as part of different Jobs. All our jobs run as a Service Account user but jobs are started manually by various users. I need to find out which user started it, as inside stored procedure, as current user, it will always show service account. Also for Values of Paramters, is there a better dynamic way of finding this out? rather then setting a value for a variable manually. I was hopping to use output from INPUTBUFFER but it only shows the name of the parameter not values.

If someone can guide me regarding the back end table structure and script for this auditing SP, it will be really helpful. Also any more ideas for improvement are welcome as well.

My main confusion:
I believe they had some table where these stored procedure values were stored and if the SP is running already, they did update in the record then doing an Insert but how would they identify to do an insert instead of update in the scenario where stored procedure failed critically and catch block wasn't executed.

Best Answer

Here is a structure that is at least very close.

There is no programmatic way to get the parameters (unfortunately). You need to format them into XML to pass in.

The Login that initiates a SQL Agent job seems to only be logged in the message column of msdb.dbo.sysjobhistory, for step_id = 0. This value can be extracted, but not during the execution of the job.

You get ObjectID to pass in from @@PROCID.

Below is the schema (2 tables) and stored procedures (3 procs). The concept is to separate "init", "in process", and "completed (success or error)" logging. This allows for setting certain columns only at the appropriate time (e.g. only need to set DatabaseID, StartedAt, etc at the very beginning). Separating the type of event also makes it easier to have event-specific logic (yes, can have it even in a single proc, but then you still have all the input parameters when you only need a subset per each event-type).

A "process" record get updated via its IDENTITY (and clustered PK) value. This is another benefit of having the "event type" separation: it makes it much easier to handle capturing the SCOPE_IDENTITY() and passing it back to be used for the two other logging stored procedures. If a stored procedure fails and doesn't go to the CATCH block, then there is no need to worry about accidentally updating that process record as the next time any stored procedure (that is being logged) starts, it will get a new / unique ID to update.

Cleanup (optional) and Schema

/* -- optional cleanup
DROP PROCEDURE [dbo].[ProcessLogDemo];

DROP PROCEDURE [Logging].[ProcessLog_Log];
DROP PROCEDURE [Logging].[ProcessLog_Start];
DROP PROCEDURE [Logging].[ProcessLog_Stop];

DROP TABLE [Logging].[ProcessLog];
DROP TABLE Logging.[Status];

DROP SCHEMA [Logging];
*/

CREATE SCHEMA [Logging];
GO

Tables and Indexes

CREATE TABLE Logging.[Status]
(
  [StatusID] TINYINT NOT NULL 
              CONSTRAINT [PK_Status] PRIMARY KEY CLUSTERED,
  [StatusName] VARCHAR(50) NOT NULL
);

CREATE TABLE [Logging].[ProcessLog]
(
  ProcessLogID  INT NOT NULL IDENTITY(-2147483648, 1) -- start at INT min value
                 CONSTRAINT [PK_ProcessLog] PRIMARY KEY CLUSTERED,
  DatabaseID INT NOT NULL,
  ObjectID INT NULL, -- NULL = ad hoc query
  SessionID SMALLINT NOT NULL
             CONSTRAINT [DF_ProcessLog_SessionID] DEFAULT (@@SPID),
  Step TINYINT NOT NULL, -- if you have more than 255 steps, consult psychiatrist
  StatusID TINYINT NOT NULL
            CONSTRAINT [FK_ProcessLog_Status]
                FOREIGN KEY REFERENCES [Logging].[Status]([StatusID]),
  Remarks NVARCHAR(MAX) NULL, -- or maybe VARCHAR(MAX)?
  Params XML NULL,
  RowsSelected INT NULL,
  RowsInserted INT NULL,
  RowsUpdated INT NULL,
  RowsDeleted INT NULL,
  StartedBy [sysname] NULL,
  StartedAt DATETIME2 NOT NULL
             CONSTRAINT [DF_ProcessLog_StartedAt] DEFAULT (SYSDATETIME()),
  UpdatedAt DATETIME2 NULL, -- use to show progress / "heartbeat"
  StoppedAt DATETIME2 NULL
);
GO

Stored Procedure to call at the very beginning of "logged" stored procedures

CREATE PROCEDURE [Logging].[ProcessLog_Start]
(
  @DatabaseID INT,
  @ObjectID INT,
  @Params XML,
  @ProcessLogID INT = NULL OUTPUT
)
AS
SET NOCOUNT ON;

-- First, capture the MAX "instance_id" from sysjobhistory if this process is a SQL
-- Server Agent job (use later to get the "invoked by" Login), else grab the Login.
DECLARE @StartedBy [sysname];

IF (EXISTS(
           SELECT *
           FROM   sys.dm_exec_sessions sdes
           WHERE  sdes.[session_id] = @@SPID
           AND    sdes.[program_name] LIKE N'SQLAgent - TSQL JobStep (%'))
BEGIN
  DECLARE @JobID UNIQUEIDENTIFIER;

  SELECT @JobID = CONVERT(UNIQUEIDENTIFIER, 
                           CONVERT(BINARY(16),
                                   SUBSTRING(sdes.[program_name],
                                        CHARINDEX(N'(Job 0x', sdes.[program_name]) + 5,
                                             34), 1
                                  )
                          )
  FROM  sys.dm_exec_sessions sdes
  WHERE sdes.[session_id] = @@SPID;

--SELECT @JobID;

  SELECT @StartedBy = N'sysjobhistory.instance_id: '
                       + CONVERT(NVARCHAR(20), MAX(sjh.[instance_id]))
  FROM   msdb.dbo.sysjobhistory sjh
  WHERE  sjh.[job_id] = @JobID;
END;
ELSE
BEGIN
  SET @StartedBy = ORIGINAL_LOGIN();
END;

-- Now it should be safe to create a new entry
INSERT INTO [Logging].[ProcessLog] ([DatabaseID], [ObjectID], [Step], [StatusID],
                                    [Params], [StartedBy])
VALUES (@DatabaseID, @ObjectID, 0, 1, @Params, @StartedBy);

SET @ProcessLogID = SCOPE_IDENTITY();
GO

Stored Procedure to call after all but the final step

CREATE PROCEDURE [Logging].[ProcessLog_Log]
(
  @ProcessLogID INT,
  @Step TINYINT,
  @RowsSelected INT = NULL,
  @RowsInserted INT = NULL,
  @RowsUpdated INT = NULL,
  @RowsDeleted INT = NULL
)
AS
SET NOCOUNT ON;

UPDATE pl
SET    pl.[StatusID] = 2, -- In process
       pl.[Step] = @Step,
       pl.[UpdatedAt] = SYSDATETIME(),
       pl.[RowsSelected] = ISNULL(@RowsSelected, pl.[RowsSelected]),
       pl.[RowsInserted] = ISNULL(@RowsInserted, pl.[RowsInserted]),
       pl.[RowsUpdated] = ISNULL(@RowsUpdated, pl.[RowsUpdated]),
       pl.[RowsDeleted] = ISNULL(@RowsDeleted, pl.[RowsDeleted])
FROM   [Logging].[ProcessLog] pl
WHERE  pl.[ProcessLogID] = @ProcessLogID;

IF (@@ROWCOUNT = 0)
BEGIN
 RAISERROR('No initial or in-process record for ProcessLogID = %d !', 16, 1,
           @ProcessLogID);
  RETURN;
END;
GO

Stored Procedure to call after the final step and/or in a CATCH block

CREATE PROCEDURE [Logging].[ProcessLog_Stop]
(
  @ProcessLogID INT,
  @Step TINYINT,
  @StatusID TINYINT,
  @Remarks NVARCHAR(MAX) = NULL,
  @RowsSelected INT = NULL,
  @RowsInserted INT = NULL,
  @RowsUpdated INT = NULL,
  @RowsDeleted INT = NULL
)
AS
SET NOCOUNT ON;

UPDATE pl
SET    pl.[StatusID] = @StatusID, -- 3 = Success, 4 = Fail
       pl.[Step] = @Step,
       pl.[Remarks] = @Remarks,
       pl.[StoppedAt] = SYSDATETIME(),
       pl.[RowsSelected] = ISNULL(@RowsSelected, pl.[RowsSelected]),
       pl.[RowsInserted] = ISNULL(@RowsSelected, pl.[RowsInserted]),
       pl.[RowsUpdated] = ISNULL(@RowsSelected, pl.[RowsUpdated]),
       pl.[RowsDeleted] = ISNULL(@RowsSelected, pl.[RowsDeleted])
FROM   [Logging].[ProcessLog] pl
WHERE  pl.[ProcessLogID] = @ProcessLogID;

IF (@@ROWCOUNT = 0)
BEGIN
 RAISERROR('No initial or in-process record for ProcessLogID = %d !', 16, 1,
           @ProcessLogID);
  RETURN;
END;
GO

Demo stored procedure (input parameters are formatted as XML)

The reason for putting "StepNumber" in a variable is so that the value can get passed to the CATCH block. The @StepNumber variable is incremented prior to each operation. If the operation succeeds, that value is used to call the "Log" stored procedure that captures the number of rows affected for that step and the time it was called. If the operation fails, that same @StepNumber value is used to call the "Stop" stored procedure that marks the process as "failed" and passes in the error message. This makes the data less confusing since the Step column on failed records will be the step it was actually working on when the error occurred.

CREATE PROCEDURE [dbo].[ProcessLogDemo]
(
  @Param1 INT,
  @Param2 DATETIME,
  @Param3 NVARCHAR(50) = NULL
)
AS
SET NOCOUNT ON;

DECLARE @ProcessID INT,
        @DB_ID INT = DB_ID(),
        @Params XML,
        @StepNumber TINYINT;

SET @Params = (
   SELECT @Param1 AS [Param1],
          @Param2 AS [Param2],
          @Param3 AS [Param3]          
   FOR XML PATH(N'Params')
); -- missing elements mean the value == NULL
--SELECT @Params;

BEGIN TRY

  EXEC [Logging].[ProcessLog_Start]
    @DatabaseID = @DB_ID,
    @ObjectID = @@PROCID,
    @Params = @Params,
    @ProcessLogID = @ProcessID OUTPUT;

  SET @StepNumber = 1;

  -- do something

  EXEC [Logging].[ProcessLog_Log]
    @ProcessLogID = @ProcessID,
    @Step = @StepNumber,
    @RowsSelected = @@ROWCOUNT;

  SET @StepNumber = 2;

  -- do something else

  EXEC [Logging].[ProcessLog_Log]
    @ProcessLogID = @ProcessID,
    @Step = @StepNumber,
    @RowsUpdated = @@ROWCOUNT;

  SET @StepNumber = 3;

  -- do final thingy

  EXEC [Logging].[ProcessLog_Stop]
    @ProcessLogID = @ProcessID,
    @Step = @StepNumber,
    @StatusID = 3, -- success
    @RowsInserted = @@ROWCOUNT;

END TRY
BEGIN CATCH
  DECLARE @ErrorMessage NVARCHAR(MAX) = ERROR_MESSAGE();

  EXEC [Logging].[ProcessLog_Stop]
    @ProcessLogID = @ProcessID,
    @Step = @StepNumber,
    @StatusID = 4, -- fail
    @Remarks = @ErrorMessage;
END CATCH;
GO

NOTES:

With regards to getting the "invoked by" Login for SQL Server Agent jobs: the step_id = 0 record (which is the only place that this info exists) does not exist until the job completes (success or failure). Hence, it isn't available while the stored procedure is running, let alone at the beginning. For now we capture the MAX(sjh.[instance_id]) FROM msdb.dbo.sysjobhistory sjh for the currently executing job for the current session. Later (i.e. after the job completes), that can get replaced with the job invoker Login.
I would generally recommend against adding this type of logging to Stored Procedures that are executed very frequently as the additional read and write operations will have a negative impact on performance.

ADDENDUM

Here is an Inline Table-Valued Function (ITVF) to get the job outcome info (including the "invoked by" user or schedule or whatever) based on the instance_id value that was captured into the ProcessLog.StartedBy column. The instance_id value returned in the result set is the row for step_id = 0.

CREATE FUNCTION dbo.GetSqlServerAgentJobOutcome
(
  @InstanceID INT
)
RETURNS TABLE
AS RETURN

WITH cte AS
(
  SELECT TOP (1)
         sjh.[instance_id],
         sjh.job_id,
         sjh.[message],
         sjh.[run_date],
         sjh.[run_time],
         sjh.[run_duration],
         sjh.[run_status],
         sjh.[sql_message_id],
         sjh.[sql_severity],
         (CHARINDEX(N' was invoked by ', sjh.[message]) + 16) AS [invoker_begin],
         CHARINDEX(N'.  The last step to run', sjh.[message]) AS [invoker_end]
  FROM   msdb.dbo.sysjobhistory  sjh
  WHERE  sjh.[job_id] = (SELECT sjh2.[job_id]
                         FROM   msdb.dbo.sysjobhistory sjh2
                         WHERE  sjh2.[instance_id] = @InstanceID)
  AND    sjh.[step_id] = 0
  AND    sjh.[instance_id] >= @InstanceID
  ORDER BY instance_id ASC
)
SELECT [instance_id], [job_id],
       --[message],
       [run_date], [run_time],
       [run_duration], [run_status],
       [sql_message_id], [sql_severity],
       SUBSTRING([message], invoker_begin, ([invoker_end] - [invoker_begin]))
          AS [InvokedBy]
FROM   cte;
GO

QUESTION #1

What is error in this procedure?

You seem to have some scope confusion on the variables

ANSWER TO QUESTION #1

PROBLEM : Your parameters have identical names to column names in the tables. This could produce some unpredictable results.

SOLUTION : Change the names of the parameters so that they are distinct from the column names

create procedure accountstatus

(

    IN  inmode              varchar(27),
    IN  given_AccountStatus_id    int,
    IN  given_AccountStatus       varchar(255),
    IN  given_CreatedOn           datetime,
    IN  given_CreatedBy           varchar(255),
    IN  given_UpdatedOn           datetime,
    IN  given_UpdatedBy           varchar(255),
    IN  given_is_active           bit)

    Begin

    if inmode   =   'insert'
    then
        insert into accountstatus
        (AccountStatus_id, Account_Status, CreatedOn, CreatedBy, UpdatedOn, UpdatedBy, is_active)
        values
        (given_AccountStatus_id, given_Account_Status, given_CreatedOn, given_CreatedBy, given_UpdatedOn, given_UpdatedBy, given_is_active);
    end if;

    /*update*/

    if inmode   =   'update'
    then
        update accountstatus acc
        set
--      acc.AccountStatus_id    =   given_AccountStatus_id,  <- Not Needed for UPDATE
        acc.Account_Status      =   given_Account_Status,
        acc.CreatedOn           =   given_CreatedOn,
        acc.CreatedBy           =   given_CreatedBy,
        acc.UpdatedOn           =   given_UpdatedOn,
        acc.UpdatedBy           =   given_UpdatedBy,
        acc.is_active           =   given_is_active
        where
        acc.AccountStatus_id    =   given_AccountStatus_id;

    end if;

    /*delete*/

    if inmode   =   'delete'
    then
        update  accountstatus acc
        set
--      acc.AccountStatus_id    =   given_AccountStatus_id, <- Not Needed for DELETE
        acc.is_active           =   0
        where
        acc.AccountStatus_id    =   given_AccountStatus_id;
    
    end if;

    /*select*/

    if inmode   =   'select'
    then
        select * from accountstatus acc
        where
        acc.AccountStatus_id    =   given_AccountStatus_id;
    end if;
end

CAVEAT : Please note that I commented out two lines

QUESTION #2

Is there any other ways to implement this procedure?

ANSWER TO QUESTION #2

You could use triggers

Aug 15, 2011 : Performance of a Trigger vs Stored Procedure in MySQL
Apr 06, 2012 : How to speed up audit trigger?

QUESTION #3

How it will effect the performance of the database?

ANSWER TO QUESTION #3

Doing bulk operations can make the MySQL server process to tedious work and bog it down. Here is other posts showing how to use SQL efficiently to replace a trigger and stored procedure, why too many triggers can be bad, and how as little code as possible

Aug 11, 2011 : Policies RE database triggers in well-designed applications?
Aug 12, 2011 : Performance of a Trigger vs Stored Procedure in MySQL
Dec 23, 2011 : How to set up triggers in MySQL for copying a field

EPILOGUE

The simpler the code in the Stored Procedure or Trigger, the less impact on performance, especially on bulk INSERTs, UPDATEs, and DELETEs.

Please consider the Storage Engine and its locking characteristics (using MyISAM) when using triggers and the autocommit behavior (if using InnoDB).

Sql-server – how to Update Value in local tabel when job Finished

Because there are several apparently semi-independent jobs running, I would suggest implementing a status table and creating a trigger for that table. It depends on how complex you want to be, but let's keep it to a very simple example. Perhaps a table:

CREATE TABLE dbo.JobGroupStatus
(Job1 INT,
 Job2 INT,
 Job3 INT,
 Job4 INT,
 Job5 INT
 Job6 INT);

When the first job starts it could set all columns to 0. Then as job one finishes it would "UPDATE dbo.JobGroupStatus SET Job1 = 1", then Job2 when it finishes would update Job2, etc. Create a trigger on that table that discerns when all jobs have finished.

 CREATE TRIGGER UPD_JobGroupStatus ON dbo.JobGroupStatus
 FOR UPDATE 
 AS
 IF (SELECT Job1+Job2+Job3+Job4+Job5+Job6 
     FROM dbo.JobGroupStatus) = 6 
   Update dbo.FinishedJobGroup Set AllDone = 1;
  GO

Of course, you would need to have a periodic check that would determine that apparently all 6 jobs will not finish and report failure.

This little snippet of code is just a toy, not a serious production program. But perhaps it offers you an idea or two about how you might approach your problem.