WilberBeast

Thank you to Adam Aspin, my much respected friend, who introduced me to, and inspires me in, all things SQL.

SSIS packages, especially once loaded onto a production server are very opaque. There is very little information provided about the progress of the package and no stats are available regarding which tasks are taking the most time, therefore some form of logging is essential.

In this post I’ll outline a very simple and easy to implement approach to logging that can be applied to the SSIS package as well as stored procedures that are called within it.

In order to maintain separation of log info from any particular application it would be preferable to create a separate logging database, however it is not essential. In this post I’ll create a ‘LOG’ schema and create the tables and stored procedures within this schema.

In brief we will:

1. Create a reference table and data related to logging.
2. Create a table to store the log entries.
3. Create stored procedures to facilitate the logging.
4. Create events within an SSIS package to add logging information.
5. Annotate a sample stored procedure to include logging.
6. Review the logging output.

Create a reference table and data related to logging

The only reference table we need is to define the type of each log entry. Primarily we need start and stop entries for each type of item we are going to track. Additionally I have added an extra two types, one for information and one for errors.

By using negative numbers mirroring the positive numbers it makes it much easier to see elements start and stop when reviewing a log.

CREATE TABLE LOG.LogEntryType (
    log_entry_type_id smallint NOT NULL,
    name varchar(50) NOT NULL,
    CONSTRAINT PK_LogStepType PRIMARY KEY CLUSTERED (log_entry_type_id ASC)
)
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (1, 'SSIS Package Start')
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (-1, 'SSIS Package Finish')
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (2, 'SSIS Task Start')
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (-2, 'SSIS Task Finish')
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (3, 'Stored Procedure Start')
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (-3, 'Stored Procedure Finish')
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (4, 'Stored Procedure Step Start')
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (-4, 'Stored Procedure Step Finish')
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (99, 'Information')
INSERT LOG.LogEntryType (log_entry_type_id, name) VALUES (100, 'Error')

Create a table to store the log entries

CREATE TABLE LOG.LogEntry(
    log_entry_id bigint IDENTITY(1,1) NOT NULL,
    log_entry_type_id smallint NOT NULL,
    date_created datetime NOT NULL,
    entity_id varchar(50) NULL,
    entity_name varchar(2000) NOT NULL,
    parent_entity_id varchar(50) NULL,
    parent_entity_name varchar(2000) NULL,
    value bigint NULL,
    description varchar(2000) NULL,
    CONSTRAINT PK_LogEntry PRIMARY KEY NONCLUSTERED (log_entry_id ASC)
)

ALTER TABLE LOG.LogEntry WITH CHECK 
ADD CONSTRAINT FK_LogEntry_LogEntryType FOREIGN KEY(log_entry_type_id)
REFERENCES LOG.LogEntryType (log_entry_type_id)

ALTER TABLE LOG.LogEntry CHECK CONSTRAINT FK_LogEntry_LogEntryType

Create stored procedures to facilitate the logging.

The code below creates the stored procedure required to add a simple log entry. The parameters will become clear as we work on adding logging to an SSIS package.

CREATE Procedure LOG.AddLogEntry
/******************************************************************************
Description:
    Adds an entry to the log.
History:
    05-Oct-2011 S.Wilber
        Created
******************************************************************************/
    @log_entry_type_id smallint
   ,@entity_id varchar(50)
   ,@entity_name varchar(2000)
   ,@parent_entity_id varchar(50) = Null
   ,@parent_entity_name varchar(2000) = Null
   ,@error_code int = Null
   ,@error_description varchar(2000) = Null
   ,@value bigint = Null
   ,@value_description varchar(2000) = Null
As

Insert          LOG.LogEntry 
                (
                    log_entry_type_id
                   ,date_created
                   ,entity_id
                   ,entity_name
                   ,parent_entity_id
                   ,parent_entity_name
                   ,value
                   ,description
                )
Values          (
                    @log_entry_type_id
                   ,GetDate()
                   ,@entity_id
                   ,@entity_name
                   ,@parent_entity_id
                   ,@parent_entity_name
                   ,Case When @error_code Is Not Null Then Convert(bigint, @error_code) Else @value End
                   ,Case When @error_code Is Not Null Then @error_description Else @value_description End
                )

The following code creates the stored procedure that we are going to use to add logging to our own stored procedures. This code is a little more complex as I want to minimise the logging code that I will need to add to any stored procedure. Rather than adding a log entry to start and stop each step within a store procedure I just want to log the start; the code below will automatically add the stop for the previous step as well as closing off the last step when finishing the stored procedure.

CREATE Procedure LOG.AddProcedureLogEntry
/******************************************************************************
Description:
    Adds an entry to the log. This is a wrapper to AddLogEntry but tailored
    for stored procedures.
    Depending on the combination of parameters it closes the previous step
    and starts the current step
History:
    05-Oct-2011 S.Wilber
        Created
******************************************************************************/
    @proc_id int
   ,@step_number smallint = Null Output
   ,@step_description varchar(2000) = Null
   ,@close_only bit = 0
   ,@parent_entity_id varchar(50) = Null
   ,@parent_entity_name varchar(2000) = Null
As


Declare         @log_entry_type_id smallint
               ,@entity_id varchar(50) = Convert(varchar(10), @proc_id) + '-' + Convert(varchar(10), @@spid)
               ,@entity_name varchar(2000) = Object_Name(@proc_id)
               ,@error_code int = Null
               ,@error_description varchar(2000) = Null
               ,@value bigint
               ,@value_description varchar(2000)
               ,@log_entry_type_proc_start smallint = 3
               ,@log_entry_type_proc_end smallint = -3
               ,@log_entry_type_proc_step_start smallint = 4
               ,@log_entry_type_proc_step_end smallint = -4


-- if this is for a step - close off the previous step and then make a new one
If @step_number Is Not Null
  Begin
    If @step_number != 0
      Begin
        Set             @log_entry_type_id = @log_entry_type_proc_step_end
        Set             @value = Convert(bigint, @step_number)
        
        -- get the last description
        Select Top 1    @value_description = description
        From            Log.LogEntry
        Where           log_entry_type_id = @log_entry_type_proc_step_start
        And             entity_id = @entity_id
        And             value = @value
        Order By        log_entry_id desc
        
        Exec LOG.AddLogEntry
           @log_entry_type_id
          ,@entity_id
          ,@entity_name
          ,@parent_entity_id
          ,@parent_entity_name
          ,@error_code
          ,@error_description
          ,@value
          ,@value_description
      End
        
    If @close_only != 1
      Begin
        -- increment the step number
        Set             @step_number = @step_number + 1
        Set             @log_entry_type_id = @log_entry_type_proc_step_start
        Set             @value = Convert(bigint, @step_number)
        Set             @value_description = IsNull(@step_description, 'Step: ' + Convert(varchar(10), @step_number))

        Exec LOG.AddLogEntry
           @log_entry_type_id
          ,@entity_id
          ,@entity_name
          ,@parent_entity_id
          ,@parent_entity_name
          ,@error_code
          ,@error_description
          ,@value
          ,@value_description
        
      End  
  End
Else
  Begin

    -- check that the last step has been closed
    Select Top 1    @value_description = description
                   ,@step_number = Convert(smallint, value)
                   ,@log_entry_type_id = log_entry_type_id
    From            Log.LogEntry
    Where           entity_id = @entity_id
    Order By        log_entry_id desc
    
    If @log_entry_type_id = @log_entry_type_proc_step_start
      Begin
        Set             @log_entry_type_id = @log_entry_type_proc_step_end
        Set             @value = Convert(bigint, @step_number)
        
        Exec LOG.AddLogEntry
           @log_entry_type_id
          ,@entity_id
          ,@entity_name
          ,@parent_entity_id
          ,@parent_entity_name
          ,@error_code
          ,@error_description
          ,@value
          ,@value_description
      End

    -- now just write the procedure start/end              
    Set @log_entry_type_id = Case When @close_only = 0 Then @log_entry_type_proc_start Else @log_entry_type_proc_end End
    Set @value = Null
    Set @value_description = Null
    
    Exec LOG.AddLogEntry
       @log_entry_type_id
      ,@entity_id
      ,@entity_name
      ,@parent_entity_id
      ,@parent_entity_name
      ,@error_code
      ,@error_description
      ,@value
      ,@value_description

  End    

Create events within an SSIS package to add logging information.

Logging within SSIS is performed by carrying out actions triggered by ‘events’.

The events we are interested in here are:

• OnPreExecute – triggered just before the package or a task within the package starts to execute.
• OnPostExecute – triggered just after the package or a task within the package has executed.
• OnError – trigged when an error occurs.

Now very conveniently, if the events are created at the package scope, i.e. click on the background of your package before clicking on the ‘Event Handlers’ tab, then the events fire both for the package starting and stopping, but also for each and every task starting and stopping. Therefore if we called our stored procedure ‘LOG.AddLogEntry’ from within the events, then the whole package would be logged.

However, before you dive in, we will need to be able to differentiate between events triggered off for tasks and for the package, and we’ll do this by using a few little variables evaluated from expressions.

The first step is to create three variables, in the scope of the event, that will contain some of the values that we will send to the ‘LOG.AddLogEntry’ stored procedure. The details of the variables are given below, but note that in the properties for the variable, set ‘EvaluateAsExpression’ to ‘True’.

The screenshot below shows the ‘OnPreExecute’ event, which is the same as on the ‘OnPostExecute’ event. You can see the three variables required on the left hand side (note their scope) and also the Execute SQL Task that will call the stored procedure to add the log entry.

Screenshot - OnPreExecute

For the execution of the stored procedure to add the log entry I’ve used an ADO.NET connection due to the clarity of the parameter mapping.

The Execute SQL Task merely calls the stored procedure ‘LOG.AddLogEntry’ as shown in the screenshot below.

Screenshot - Execute SQL Task

The parameters are mapped as shown in the screenshot below.

Screenshot - Execute SQL Task Parameters

The PostExecute event is very similar to the PreExecute event and I won’t go into further details here.

I also like to catch the OnError event, and its implementation is very similar. The ‘LogEntryTypeID’ variable is still require, but it does not need to be an expression and its value can just be set to 100.

Screenshot - OnError

The parameters require are slightly different and are shown in the following screenshot.

Screenshot - OnError Parameters

Annotate a sample stored procedure to include logging.

Adding logging to long and complex stored procedures can be a really valuable aid in clearly identifying long running sections or for pinning down errors or unexpected flow.

Since we have already created the stored procedure for logging from stored procedures above, here I’ll quickly go through the changes that need to be made to add logging.

The principle behind the code for logging from a stored procedure is to minimise the impact to the logged stored procedure in terms of additional code. Thus, each time the LOG.AddProcedureLogEntry is called potentially two entries are added to the log, one to close of the previous entry, i.e. to mark the previous step as finished and a second to mark the current step as starting.

Three additional parameters can be added to your stored procedure. These will become self-explanatory below.

@log bit = 1
@log_parent_entity_id varchar(50) = null
@log_parent_entity_name varchar(2000) = null

Additional to the parameters you will need one variable to record the current step number.

Declare @log_proc_step smallint = 0

Finally I add three types of log calls within the stored procedures. Note, you can dispense with the ‘if’ and the additional parameter if you always want logging to be switched on. Most of the parameters are fairly clear, but @close_only is used to instruct the procedure, in the case of a step, to only close off the previous step and not to create a new step entry, and also to differentiate between the stored procedure header/footer logging.

Stored procedure start – marking the start of the execution of the stored procedure

If @log = 1 Exec LOG.AddProcedureLogEntry @proc_id = @@ProcID, @step_number = Null, @close_only = 0, @parent_entity_id = @log_parent_entity_id, @parent_entity_name = @log_parent_entity_name

Note that @step_number is null, so this is for either the header/footer and @close_only = 0, meaning that this is for the header.

Step – marking the start of each step

If @log = 1 Exec LOG.AddProcedureLogEntry @proc_id = @@ProcID, @step_number = @log_proc_step Output, @step_description = 'Fetch Process Run IDs' ,@close_only = 0, @parent_entity_id = @log_parent_entity_id, @parent_entity_name = @log_parent_entity_name

Note the @step_description which allows you to add a note for the step. This makes reviewing the log so much more simple and I would strongly recommend going to the effort to write this note.

Stored Procedure finish – marking the end of the execution of the stored procedure

If @log = 1 Exec LOG.AddProcedureLogEntry @proc_id = @@ProcID, @step_number = Null, @close_only = 1, @parent_entity_id = @log_parent_entity_id, @parent_entity_name = @log_parent_entity_name

Note that @step_number is null, so this is for either the header/footer and @close_only = 1, meaning that this is for the footer.

Review the logging output.

So, now all the logging is in place, what does the output look like. The screenshot below shows a section from a current project copied to Excel. The data is very simplistic, but you can write additional stored procedures to report out the logging information in a more informative way, including highlighting the % time that each step has used overall, using historical runs to identify the progress in terms of % of a current run, finding the top 10 slowest steps, etc.

Just for clarification I’ve coloured logging that has come from a stored procedures in pale purple.

Screenshot - Sample Log Results in Excel