debugMinor
Stored Procedure Processing and Error Log
Viewed 0 times
storederrorlogprocedureandprocessing
Problem
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.
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.
Solution
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
You get ObjectID to pass in from
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
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
Cleanup (optional) and Schema
Tables and Indexes
Stored Procedure to call at the very beginning of "logged" stored procedures
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
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];
GOTables 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
);
GOStored 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
Code Snippets
/* -- 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];
GOCREATE 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
);
GOCREATE 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;
GOCREATE 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;
GOContext
StackExchange Database Administrators Q#151664, answer score: 5
Revisions (0)
No revisions yet.