Frequently I have been called upon to write SQL Stored Procedures (SP) that will be run by SQL Agent on a scheduled basis. Since no one and nothing (like an application front-end) are watching such SPs as they go about their duties, it is incumbent upon the intrepid developer to ensure that they perform their work flawlessly, and in those hopefully few cases where they don’t, leave a trail of bread crumbs through which their failed exploits can be tracked.
Many of my SPs must go through multiple data transformation and manipulation steps. In theory, the SP could fail at any step, although I take great pains to ensure that they fail on none of them. Proper usage of TRY/CATCH blocks are essential to making sure that failures are gracefully handled. Good logging leaves us our trail of bread crumbs, from which forensic analysis of the process failure will hopefully shed light on the cause of the failure.
I think of my SQL Agent SPs as “batch jobs,” probably because my early years were spent on IBM mainframes running OS MVS, and people that understood IBM’s Job Control Language (JCL) were king. Much of my nomenclature uses that terminology, so now you know where it comes from.
Let me say right up front, that what I am proposing is one possible way, but certainly not the only way to handle the subject topics. Improvements can no doubt be made and circumstances may dictate other specifics that I have not covered. Consider this a foundation for developing your own logging and error trapping standards, in the event that you don’t already have them.
Setting up for Logging
When I do logging, I use a permanent user-defined table that is common for all batch jobs within a database. Each log entry will contain a row detailing each step for each batch job run. I’ve identified some specific information useful at each step; however I have not taken this to the next level, which would be to log job-related records in one table and step-related records in a secondary, child table. Personally I don’t feel that data normalization is necessary, because hopefully you won’t need to use the logs very often. When you do need to use them, you’ll find that you need to construct ad-hoc queries under time pressure and you don’t want to have to worry about remembering niceties like JOIN criterion and which columns are foreign keys into the parent table.
So let’s define a table that we can use to capture our logging. In the next section, we’ll get into populating this table with useful information.
CREATE TABLE ProcessLogs
(
JobStepID BIGINT IDENTITY PRIMARY KEY
,JobName VARCHAR(128) NOT NULL
,JobStartDT DATETIME NOT NULL
,StepStartDT DATETIME NOT NULL
,StepEndDT DATETIME NOT NULL
,StepName VARCHAR(50) NOT NULL
,Row_Count INT NOT NULL
,[ERROR_NUMBER] INT NULL
,ERROR_MSG NVARCHAR(4000) NULL
,[ERROR_LINE] INT NULL
,ERROR_PROC NVARCHAR(128) NULL
,ERROR_SEV INT NULL
,[ERROR_STATE] INT NULL
,Specifics1 SQL_VARIANT NULL
,Specifics2 SQL_VARIANT NULL
,Specifics3 SQL_VARIANT NULL
,Specifics4 SQL_VARIANT NULL
,Spid INT NOT NULL
,Kpid INT NOT NULL
,[Status] VARCHAR(50) NOT NULL
,Hostname VARCHAR(50) NOT NULL
,[Dbid] INT NOT NULL
,Cmd VARCHAR(50) NOT NULL
);
GO
CREATE TYPE Process_Log AS TABLE
(
JobName VARCHAR(128) NOT NULL
,JobStartDT DATETIME NOT NULL
,StepStartDT DATETIME NOT NULL
,StepEndDT DATETIME NOT NULL
,StepName VARCHAR(50) NOT NULL
,Row_Count INT NOT NULL
,[ERROR_NUMBER] INT NULL
,ERROR_MSG NVARCHAR(4000) NULL
,[ERROR_LINE] INT NULL
,ERROR_PROC NVARCHAR(128) NULL
,ERROR_SEV INT NULL
,[ERROR_STATE] INT NULL
,Specifics1 SQL_VARIANT NULL
,Specifics2 SQL_VARIANT NULL
,Specifics3 SQL_VARIANT NULL
,Specifics4 SQL_VARIANT NULL
,Spid INT NOT NULL
,Kpid INT NOT NULL
,[Status] VARCHAR(50) NOT NULL
,Hostname VARCHAR(50) NOT NULL
,[Dbid] INT NOT NULL
,Cmd VARCHAR(50) NOT NULL
);
GOIn our CREATE TABLE statement, you’ll see a few columns whose names are also SQL keywords, so these have been [bracketed].
In the second batch, the Data Definition Language (DDL) command is creating a TABLE TYPE. You may be familiar with TABLE TYPEs being a means to pass a TABLE into a SP. In this case, we’ll be using it for something else that we’ll describe later. Notice how its structure is quite similar to our ProcessLogs TABLE, except that the column in ProcessLogs that is the PRIMARY KEY has been omitted.
If you’ve worked with TABLE TYPEs before, you probably already know they can be exposed in SQL Server Management Studio (SSMS) by clicking through the object browser: [Your Database] > Programmability > Types > User-defined Table Types, and from there you can view Columns, Keys, Constraints and Indexes for each defined TABLE TYPE.
You may also want to tuck away into your toolbox the following little script of my own design, which will expose most of the important information, particularly about the columns, for all of your defined TABLE TYPEs.
SELECT TableTypeName=CASE rn WHEN 1 THEN TableTypeName ELSE '' END
,ColumnName, ColumnType, max_length
,[precision], scale, collation_name
,[Nulls Allowed]=CASE is_nullable WHEN 1 THEN 'YES' ELSE 'NO' END
,[Is Identity]=CASE is_identity WHEN 1 THEN 'YES' ELSE 'NO' END
,[Is In Primary Key]=CASE WHEN index_column_id IS NULL THEN 'NO' ELSE 'YES' END
,[Primary Key Constraint Name]=CASE rn WHEN 1 THEN ISNULL(PKName, '') ELSE '' END
FROM
(
SELECT TableTypeName=a.name, ColumnName=b.name, ColumnType=UPPER(c.name)
,b.max_length, b.[precision], b.scale
,collation_name=COALESCE(b.collation_name, a.collation_name, '')
,rn=ROW_NUMBER() OVER (PARTITION BY a.name ORDER BY b.column_id)
,b.column_id
,b.is_nullable
,b.is_identity
,e.index_column_id
,PKName = d.name
FROM sys.table_types a
JOIN sys.columns b ON b.[object_id] = a.type_table_object_id
JOIN sys.types c
ON c.system_type_id = b.system_type_id
LEFT JOIN sys.key_constraints d ON b.[object_id] = d.parent_object_id
LEFT JOIN sys.index_columns e
ON b.[object_id] = e.[object_id] AND e.index_column_id = b.column_id
WHERE c.system_type_id = c.user_type_id
) a
--WHERE a.TableTypeName = 'Process_Log'
ORDER BY a.TableTypeName, column_id;Running that script with the WHERE clause uncommented yields a display that looks like this for the TABLE TYPE we just defined.
If you modify the structure of the ProcessLogs TABLE, you should make the identical modifications to the Process_Log TABLE TYPE. It may be possible to set up a DDL TRIGGER to handle this for you, but that level of sophistication is beyond the scope of this article.
Additional details about the columns we’ve defined will be provided as our discussion progresses.
A Sample Batch Job Stored Procedure
We’ll now move on to creating a template we can use for any SP we’ll develop in the future to perform a batch job or process. The assumption is that your SP will contain multiple SQL steps, and that some of those steps must be enclosed within a TRANSACTION because they’re doing some kind of change to underlying data tables. Our skeleton SP will require no parameters, as those will typically be unique to the batch processing requirements, and none are required to support logging or error handling.
Let’s start our SP template with the preamble, or in other words the CREATE PROCEDURE statement along with the DECLAREs we’ll need to do our logging.
Note the similarity between our local variable names and the column names we’ve defined in our process tables. The only one that is omitted is StepName, and the reason for that will be apparent in a moment.
CREATE PROCEDURE MyBatchJobProcess
AS
BEGIN
DECLARE @ProcessLog dbo.Process_Log;
DECLARE @JobName VARCHAR(128) = 'MyBatchJobProcess'
,@JobStartDT DATETIME = GETDATE()
,@StepStartDT DATETIME
,@StepEndDT DATETIME
,@Row_Count INT
,@ERROR_NUMBER INT = NULL
,@ERROR_MSG NVARCHAR(4000) = NULL
,@ERROR_LINE INT = NULL
,@ERROR_PROC NVARCHAR(128) = NULL
,@ERROR_SEV INT = NULL
,@ERROR_STATE INT = NULL
,@Specifics1 SQL_VARIANT = NULL
,@Specifics2 SQL_VARIANT = NULL
,@Specifics3 SQL_VARIANT = NULL
,@Specifics4 SQL_VARIANT = NULL
,@Spid INT = @@SPID
,@Kpid INT
,@Status VARCHAR(50)
,@Hostname VARCHAR(50)
,@Dbid INT
,@Cmd VARCHAR(50);
-- Some system process variables that we will include with each log record
SELECT TOP 1 @Kpid=kpid, @Status=[status], @Hostname=hostname, @Dbid=[dbid], @Cmd=cmd
FROM master..sysprocesses
WHERE spid = @Spid;
-- Other initializations required to handle your SP's functional requirements go here
WAITFOR DELAY '00:00:01'; -- Remove this once you convert the template to a real SP.
ENDIn our preamble, we’ve set the @JobStartDT to the current time once, as it will remain the same throughout the execution of our SP. Likewise @JobName is just the static name of our SP. All of our local variables prefixed as @ERROR_ (and a few others) are set to NULL and we sincerely hope the @ERROR_ variables will stay that way as our SP executes. The WAITFOR DELAY statement can be removed when you’ve defined some actual work to be done during the initialization step.
Note that in our preamble we have also defined a local table variable @ProcessLog based on the TABLE TYPE we created earlier. The reason why we created this as a TABLE TYPE should now be apparent. We expect to have many batch SPs in our application that will share the same logging table, so we have simplified the declaration of our local table variable using the TABLE TYPE. We’ll describe why we need this local table variable when we get to error handling a little later.
The intent of the remainder of the code in the preamble should be explained by the comments.
Completing our Logging Template
We will now develop our SP template to include all of the aspects we’ll need for logging. We’ll show only the SQL code for each part, explaining it in turn (i.e., without the preamble). At the end we’ll present the entire template.
Looking at the last comment in the preamble, you see that we’ve reserved a place for initializing all the local variables, temp or table variables, etc. that your SP needs to satisfy the functional requirements it is delivering. After the initialization is complete, we’ll want to create an initial log entry like this:
SELECT @StepStartDT = @JobStartDT, @StepEndDT = GETDATE(), @Row_Count = 0;
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'JOB INITIALIZATION COMPLETE'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;You can see now why we didn’t need the @StepName local variable – we’ve simply hard-coded the step description in our logging INSERT, and we’ll do this for each log entry.
Depending on what your initialization does, you may want to set @Row_Count to the results (@@ROWCOUNT) from a query or set some of the @Specifics variables to record what went on during the initialization. You’ll see examples of this as we progress through the next parts of the template.
-- First job step (outside of a transaction)
-- Do the work, SELECT ... INTO ... FROM ... (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
WAITFOR DELAY '00:00:02'; -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepNameh
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 1: DESC OF STEP 1'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;The above performs the work of the first step in our job (simulated by the WAITFOR DELAY statement). You may also want to capture some specifics of the step, like maybe creating a delimited list of the keys of data you retrieved into a temporary table, or the current value of an IDENTITY column using @@IDENTITY. Now you see why we chose our Specifics columns to be of TYPE SQL_VARIANT – there’s no telling what kind of useful information we might want to save there. Generally the job step should consist of a single SQL query, so that @Row_Count is indicative of the work performed.
Subsequent job steps, which we’ll include within a TRANSACTION, will be essentially identical to the first. When we introduce error handling, these will change somewhat.
BEGIN TRANSACTION T1;
-- Second job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
WAITFOR DELAY '00:00:03'; -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 2: DESC OF STEP 2'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
-- Third job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
WAITFOR DELAY '00:00:04'; -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 3: DESC OF STEP 3'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
COMMIT TRANSACTION T1;Finally, at the end of our template we’re going to want to do two things: 1) purge the log history that’s old and probably no longer useful and 2) write a final log entry indicating the job completed. You’ll need to decide how long to keep your log entries but usually 30-60 days is sufficient.
-- Penultimate job step (purge the log)
SELECT @StepStartDT = GETDATE();
DELETE dbo.ProcessLogs
WHERE JobName = @JobName AND JobStartDT < DATEADD(day, -30, @JobStartDT);
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP x: PURGE LOG'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
-- Final step to note job complete
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, GETDATE(), GETDATE(), 'JOB COMPLETE'
,0
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;We’ve recorded the total number of process log rows purged in the penultimate step and set step start date/time and step end/date time to the same time on the final step.
Our complete logging template now looks like this:
CREATE PROCEDURE dbo.MyBatchJobProcess
AS
BEGIN
DECLARE @ProcessLog dbo.Process_Log;
DECLARE @JobName VARCHAR(128) = 'MyBatchJobProcess'
,@JobStartDT DATETIME = GETDATE()
,@StepStartDT DATETIME
,@StepEndDT DATETIME
,@Row_Count INT
,@ERROR_NUMBER INT = NULL
,@ERROR_MSG NVARCHAR(4000) = NULL
,@ERROR_LINE INT = NULL
,@ERROR_PROC NVARCHAR(128) = NULL
,@ERROR_SEV INT = NULL
,@ERROR_STATE INT = NULL
,@Specifics1 SQL_VARIANT = NULL
,@Specifics2 SQL_VARIANT = NULL
,@Specifics3 SQL_VARIANT = NULL
,@Specifics4 SQL_VARIANT = NULL
,@Spid INT = @@SPID
,@Kpid INT
,@Status VARCHAR(50)
,@Hostname VARCHAR(50)
,@Dbid INT
,@Cmd VARCHAR(50);
-- Some system process variables that we will include with each log record
SELECT TOP 1 @Kpid=kpid, @Status=[status], @Hostname=hostname, @Dbid=[dbid], @Cmd=cmd
FROM master..sysprocesses
WHERE spid = @Spid;
-- Other initializations required to handle your SP's functional requirements go here
WAITFOR DELAY '00:00:01'; -- Remove this once you convert the template to a real SP.
SELECT @StepStartDT = @JobStartDT, @StepEndDT = GETDATE(), @Row_Count = 0;
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'JOB INITIALIZATION COMPLETE'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
-- First job step (outside of a transaction)
-- Do the work, SELECT ... INTO ... FROM ... (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
WAITFOR DELAY '00:00:02'; -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 1: DESC OF STEP 1'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
BEGIN TRANSACTION T1;
-- Second job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
WAITFOR DELAY '00:00:03'; -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 2: DESC OF STEP 2'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
-- Third job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
WAITFOR DELAY '00:00:04'; -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 3: DESC OF STEP 3'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
COMMIT TRANSACTION T1;
-- Penultimate job step (purge the log)
SELECT @StepStartDT = GETDATE();
DELETE dbo.ProcessLogs
WHERE JobName = @JobName AND JobStartDT < DATEADD(day, -30, @JobStartDT);
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP x: PURGE LOG'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
-- Final step to note job complete
INSERT INTO dbo.ProcessLogs
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, GETDATE(), GETDATE(), 'JOB COMPLETE'
,0
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
ENDAt this time, we could actually run the SP and see some results created in the log. Note that the run will take about 10 seconds to complete.
Adding Error Handling to our SP Template
Our next step will be to add a skeleton for error handling, using TRY/CATCH, to the code within the TRANSACTION. We could also include it for initialization or step one, however for this article we’ll omit that, because the important thing to demonstrate is how the transaction should be rolled back in the event an error occurs.
To support error handling, we’ll need to add one additional local variable to those DECLAREd in our preamble. Initially, we’ll show how to implement only the TRY/CATCH blocks around the work being done for step two:
DECLARE @Error_Count INT = 0;
-- Second job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
BEGIN TRY
WAITFOR DELAY '00:00:03'; -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now (within the TRY).
END TRY
BEGIN CATCH
SELECT @ERROR_NUMBER = ERROR_NUMBER()
,@ERROR_PROC = ERROR_PROCEDURE()
,@ERROR_SEV = ERROR_SEVERITY()
,@ERROR_STATE = ERROR_STATE()
,@ERROR_LINE = ERROR_LINE()
,@ERROR_MSG = ERROR_MESSAGE()
,@Error_Count = @Error_Count + 1
,@Row_Count = 0
,@StepEndDT = GETDATE();
END CATCH
-- Within the transaction we want to capture logging to the TABLE variable
-- so it can be used upon ROLLBACK
INSERT INTO @ProcessLog
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 2: DESC OF STEP 2'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=CASE WHEN @Error_Count <> 0 THEN 'STEP SKIPPED DUE TO PRIOR ERRORS' END
,@Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL
,@ERROR_NUMBER=NULL, @ERROR_MSG=NULL, @ERROR_LINE=NULL
,@ERROR_PROC=NULL, @ERROR_SEV=NULL, @ERROR_STATE=NULL;We have chosen to add a TRY/CATCH block around each SQL step within the transaction. An alternative approach would put all of those steps into a single TRY block, but personally I like this better because it offers more granular control at a small price in logic complexity.
Note that we are no longer inserting into our permanent ProcessLogs TABLE; rather now we are inserting into our TABLE variable @ProcessLog (declared as TYPE @Process_Log). The reason we’ve done this is because in the (hopefully) unlikely event we need to ROLLBACK our transaction, we don’t want to lose our logged information (TABLE variables are not subject to ROLLBACKs like a temporary or permanent table would be).
Step three (the second step in the transaction will now be executed only if @Error_Count = 0, and note how at the end of the prior bit of code we put a message into @Specifics1 to show that the next step will be skipped. Here is how the transaction now looks including checking whether and executing a ROLLBACK when needed.
BEGIN TRANSACTION T1;
-- Second job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
BEGIN TRY
WAITFOR DELAY '00:00:03'; -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now (within the TRY).
END TRY
BEGIN CATCH
SELECT @ERROR_NUMBER = ERROR_NUMBER()
,@ERROR_PROC = ERROR_PROCEDURE()
,@ERROR_SEV = ERROR_SEVERITY()
,@ERROR_STATE = ERROR_STATE()
,@ERROR_LINE = ERROR_LINE()
,@ERROR_MSG = ERROR_MESSAGE()
,@Error_Count = @Error_Count + 1
,@Row_Count = 0
,@StepEndDT = GETDATE();
END CATCH
-- Within the transaction we want to capture logging to the TABLE variable
-- so it can be used upon ROLLBACK
INSERT INTO @ProcessLog
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 2: DESC OF STEP 2'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=CASE WHEN @Error_Count <> 0 THEN 'STEP SKIPPED DUE TO PRIOR ERRORS' END
,@Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL
,@ERROR_NUMBER=NULL, @ERROR_MSG=NULL, @ERROR_LINE=NULL
,@ERROR_PROC=NULL, @ERROR_SEV=NULL, @ERROR_STATE=NULL;
-- Third job step (inside of a transaction)
IF @Error_Count = 0
BEGIN
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
BEGIN TRY
WAITFOR DELAY '00:00:04'; -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
END TRY
BEGIN CATCH
SELECT @ERROR_NUMBER = ERROR_NUMBER()
,@ERROR_PROC = ERROR_PROCEDURE()
,@ERROR_SEV = ERROR_SEVERITY()
,@ERROR_STATE = ERROR_STATE()
,@ERROR_LINE = ERROR_LINE()
,@ERROR_MSG = ERROR_MESSAGE()
,@Error_Count = @Error_Count + 1
,@Row_Count = 0
,@StepEndDT = GETDATE();
END CATCH
END
INSERT INTO @ProcessLog
(
JobName, JobStartDT, StepStartDT, StepEndDT, StepName
,Row_Count
,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
,Specifics1, Specifics2, Specifics3, Specifics4
,Spid, Kpid, [Status], Hostname, [Dbid], Cmd
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 3: DESC OF STEP 3'
,@Row_Count
,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
,@Specifics1, @Specifics2, @Specifics3, @Specifics4
,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
-- Set @Specifics1 here like shown after step 2 if > 2 steps in the trans
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL
,@ERROR_NUMBER=NULL, @ERROR_MSG=NULL, @ERROR_LINE=NULL
,@ERROR_PROC=NULL, @ERROR_SEV=NULL, @ERROR_STATE=NULL;
IF @Error_Count = 0 AND XACT_STATE() = 1 COMMIT TRANSACTION T1;
ELSE IF XACT_STATE() <> 0 ROLLBACK TRANSACTION T1;
INSERT INTO ProcessLogs
SELECT * FROM @ProcessLog;If you now run the SP again and display the log, you’ll see another six records added to the ProcessLogs TABLE because we INSERTed all the rows from our TABLE variable into it. Our template is now complete and this can be found in the resources file as: CREATE PROCEDURE MyBatchJobProcess.sql.
Simulating Some Real Work and an Error Condition
In our SP template, we have four WAITFOR commands to simulate initialization, the first job step (outside the transaction) and two for our two steps inside of the transaction. We’ll copy the code for the second step inside of our transaction down to create a third step inside the transaction, so we can see what happens when an error occurs in the second transaction step. The new WAITFOR in our third transaction step we’ll leave as is, otherwise the other four WAITFORs will be replaced by the following simulated work:
-- Other initializations required to handle your SP's functional requirements go here --WAITFOR DELAY '00:00:01'; SELECT TOP 5000 @Error_Count = 0 * ROW_NUMBER() OVER (ORDER BY (SELECT NULL)) FROM sys.all_columns a CROSS JOIN sys.all_columns b; -- First job step (outside of a transaction) --WAITFOR DELAY '00:00:02'; SELECT * INTO #Temp FROM dbo.ProcessLogs; SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE(); DROP TABLE #Temp; -- Second job step (inside of a transaction) --WAITFOR DELAY '00:00:03'; UPDATE dbo.ProcessLogs SET JobStartDT = DATEADD(millisecond, 3, JobStartDT); SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE(); -- Third job step (inside of a transaction) --WAITFOR DELAY '00:00:04'; SELECT 1/0; SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
Note how we simulate an error in the third job step by doing a division by 0. We could have used RAISERROR of course, but we didn’t want to go into the details of how to make that work.
The new SP is in the SQL resource file: CREATE PROCEDURE MyBatchJobProcess2.sql. If you are following along and trying to do this yourself, you should see how close you came to the version in this SQL file.
When we now run this new SP and select all the rows in our ProcessLogs table, we should see something like the following:
Row counts have been recorded now in steps 1 and 2 (13 and 14, respectively), indicating the work that was completed. Note that the work done in step 2 is actually rolled back because it is inside of the transaction.
Notice how the error number, message and line are all recorded for Step 3. If we were to scroll right, we’d see the message “STEP SKIPPED DUE TO PRIOR ERRORS” recorded for step 4 in the Specifics1 column. Effectively, when step 3 failed, step 2 was rolled back and step 4 was skipped.
We have now completed an example of modifying our template to be an actual stored procedure that does some work.
Summary/Recap
We have described how to create a template of a multi-step SQL stored procedure that does logging for each step. Some of the steps occur inside of a transaction, and some outside. We have introduced error handling to all steps within the transaction and crafted that error handling so that it carefully records which steps are executed and errors associated with any step that fails.
We hope that the information presented here is useful to our valued readers when you must tackle projects requiring multiple step SPs to do batch work.
Dwain Camps
SQL Enthusiast
