Create Custom SSIS Execution Log - Part 2


By:   |   Updated: 2020-04-27   |   Comments (7)   |   Related: 1 | 2 | More > Integration Services Development

Problem

As a Data Warehouse or SQL Server BI (Business Intelligence) Developer, how I can make sure that my SQL Server Integration Services (SSIS) Packages use Azure UTC time to log events rather than my local system time while my packages are built locally, but run against Azure SQL Database during test runs?

Solution

The solution is the use of out-of-the-box UTC time function available in Integration Services Project in the form of T-SQL function as this can help to get away from time difference during logging events and test runs when your local dev machine uses GMT and your staging database is Azure SQL Database is UTC based.

This is the second part of the solution where the first part was all about the basics of a Data Warehouse and setting up an environment to create and run Integration Services Project along with setting up source and destination sample databases and a basic event logging system.

Pre-Requisites

The following things are recommended, if not essential, to understand this tip properly:

  1. Azure account setup
  2. Data Warehouse concepts particularly staging environment
  3. Basics of logging related to Data Warehouse
  4. Source database WatchesV4
  5. Staging database WatchesV4DW
  6. SSIS Package to run staging extract and implement basic logging

Please refer to the first part of the tip series if you would like to go through the details of all the above pre-requisites.

Adding Begin and End Date to Event Logging

Assuming you have successfully followed the walkthrough in the first part of the tip and now if you look at the existing event logging strategy we adopted (in the first part) it gives us information about when the package ran the last time.

Let's quickly check the logging table by running the following script:

-- (2) View Log table after extract to staging package with simple logging ran
SELECT
  d.LogId
 ,d.ProcessName
 ,d.PackageName
 ,d.PackageDate
FROM dbo.DWLog d			
Event Logging with Package Date Time

We can see the date and time when the SSIS Package ran from the above output, but this information is not enough in the long run, particularly when it comes to logging Data Warehouse events.

Adding Package Start and End Date Columns

Let's think about two scenarios which cannot be covered by this simple logging:

  1. What if the package began, but did not finish successfully due to some internal or external errors?
  2. What if we are interested to know the duration of a staging extract?

To cover the above scenarios, we do need to improve the simple logging by adding Package Start and End Date.

Let's now drop the existing audit table and create a new one with package start and end date as follows:

-- (1) Connect to WatchesV4DW database via SSMS or Azure Portal
 
-- (2) Drop existing log table
DROP TABLE DWLog 
 
---- (2) Create mini logging events table (part-2)
CREATE TABLE DWLog
(
LogId INT IDENTITY(1,1),
ProcessName VARCHAR(200),
PackageName VARCHAR(200),
PackageStartDate DATETIME2,
PackageEndDate DATETIME2,
DestinationRows INT
CONSTRAINT [PK_DWLog] PRIMARY KEY (LogId),
)			

The table should look as follows:

Adding Package Start and End Date

Adding SQL Tasks to SSIS Package

We have to remove the single SQL Task meant to note down Package date (we created earlier on) in the control flow of the staging extract SSIS Package.

Create the following SQL Tasks before and after the data flow task which runs the staging extract:

  1. SQL Begin Log (SQL Task)
  2. SQL End Log (SQL Task)

Adding SQL Begin Log Task

Please remove SQL Log Event task and add a new SQL Task called SQL Begin Log:

Adding SQL Begin Log Task

Double click the task and add the following code as SQL Statement:

Adding SQL Statement
INSERT INTO dbo.DWLog
         (ProcessName
         ,PackageName
         ,PackageStartDate
         ,PackageEndDate
         ,DestinationRows)
     VALUES
         ('Extract Table Watch to Staging'
         ,?
         ,?
         ,NULL
         ,NULL)
 
SELECT LogId FROM dbo.DWLog WHERE ProcessName='Extract Table Watch to Staging' and PackageStartDate=?
			

Add the Parameter Mapping as follows:

Adding Parameter Mapping

Add a new variable called LogId as follows:

Add a new variable called LogId

Add the newly created variable LogId in the Variable Name under Result Set table as follows:

Add LogId in Result Set

Adding SQL End Log Task

Keeping the Data Flow Task the same we have to add SQL End Log task:

Adding SQL End Log Task

Double click SQL End Log Task in the control flow and add the following T-SQL next to SQL statement under General left navigation bar:

UPDATE DWLog SET PackageEndDate=SYSDATETIME(), DestinationRows=? WHERE LogId=?			

Add the Parameter Mapping as shown below:

Adding Parameter Mapping

No need to be add anything in the Result Set.

Using Local System Time for Audit Logging

Now if you look closely at the logic of SQL Begin Log task it is obvious we are using built-in System variable to mark the start of the package as shown below:

Using built-in System Start Time

Next, to mark the finishing time of the package we are using SYSDATETIME() T-SQL function:

Using SYSDATETIME() as Package End Date and Time

Now when the package starts the system variable System::StartTime stores the current date and time from the system and as the package ends T-SQL SYSDATETIME() stores the ending time of the package again from the system, but there is an issue.

For example, if a developer runs this package on his dev machine then the start time of his local machine is going to be taken into account by PackageStartTime and since the database is an Azure SQL Database the end date and time is going to be read from Azure environment.

At the time of writing this tip, both the local UK time is the same as UTC so we may not feel any difference when the package runs, however during the summer time (BST) the local UK time is one hour ahead of UTC.

This means if I run this package during British Summer Time (BST) the end date and time (taken from Azure environment which is using UTC) of the package is going to be before the start date and time which is a technical flaw.

To prove this, I am going to change my current local time (8:22 PM) of the system to one hour ahead (9:22 PM) in order to replicate BST (British Summer Time).

Setting local time one hour ahead

Run the staging extract SSIS Package now:

Staging extract SSIS Package

Let's check the log table:

-- (1) Connect to WatchesV4DW database via SSMS or Azure Portal
 
-- View audit log
-- (2) View Log table after setting local time one hour ahead to replicate BST (British Summer Time)
SELECT
  d.LogId
 ,d.ProcessName
 ,d.PackageName
 ,FORMAT(d.PackageStartDate,'dd-MMM-yyyy hh:mm:ss tt') as StartTime
 ,FORMAT(d.PackageEndDate,'dd-MMM-yyyy hh:mm:ss tt') as EndTime
FROM dbo.DWLog d			

The output is as follows:

Package Start End Time is before Start Time

We can clearly see that the Project end time is before the project began (Start Time) which is why using the local time of the dev machine is not going to work all the year because as soon as British Summer Time kicks in, there is going to be a problem as shown above.

Let's run the staging extract (SSIS Package) with the same settings one more time.

Using System UTC for Audit Logging

Now to solve the one hour ahead problem when we it is British Summer Time, we need to replace System::PackageStart variable that stores UTC time using GETUTCDATE() function.

This can be done by replacing the existing SQL Statement used in SQL Begin Log task with the following:

INSERT INTO dbo.DWLog
         (ProcessName
         ,PackageName
         ,PackageStartDate
         ,PackageEndDate
         ,DestinationRows)
     VALUES
         ('Extract Table Watch to Staging'
         ,?
         ,GETUTCDATE()
         ,NULL
         ,NULL)
 
SELECT LogId FROM dbo.DWLog WHERE ProcessName='Extract Table Watch to Staging' 
ORDER BY LogId DESC

Remove all the other variables in the Parameter Mapping except PackageName:

Removing Variables Except PackageName

Now run the staging extract package (making sure we have still replicated British Summer Time which is one hour ahead):

Staging Extract (SSIS Package) Run

Check the audit log this time as follows:

-- (1) Connect to WatchesV4DW database via SSMS or Azure Portal
 
-- View audit log
-- (2) View Log table after setting local time one hour ahead to replicate BST (British Summer Time)
SELECT
  d.LogId
,d.ProcessName
,d.PackageName
,FORMAT(d.PackageStartDate,'dd-MMM-yyyy hh:mm:ss tt') as StartTime
,FORMAT(d.PackageEndDate,'dd-MMM-yyyy hh:mm:ss tt') as EndTime
FROM dbo.DWLog d			

The output is as follows:

Package start and end time logged correctly after using UTC time

Congratulations, you have successfully resolved time difference problem when running the staging extract (SSIS Package) locally on your dev machine by exclusively specifying UTC to mark the start time rather than using the system start time.

Next Steps
  • Please try adding duration of the package by adding a new column Duration and calculating it using a date time function to improve your data warehouse audit log strategy
  • Please try adding another staging extract package by adding the same logging method and then run both packages by a master package
  • Please go through the tip SQL Server Date and Time Functions with Examples to get a few more ideas of how to use date and time


Last Updated: 2020-04-27


get scripts

next tip button



About the author
MSSQLTips author Haroon Ashraf

Haroon Ashraf's interests are Database-Centric Architectures and his expertise includes development, testing, implementation and migration along with Database Life Cycle Management (DLM).

View all my tips





More SQL Server Solutions











Post a comment or let the author know this tip helped.

All comments are reviewed, so stay on subject or we may delete your comment. Note: your email address is not published. Required fields are marked with an asterisk (*).

*Name
*Email
Email me updates

Signup for our newsletter

I agree by submitting my data to receive communications, account updates and/or special offers about SQL Server from MSSQLTips and/or its Sponsors. I have read the privacy statement and understand I may unsubscribe at any time.





Thursday, May 14, 2020 - 12:26:28 PM - Abdul Khan Back To Top

Thanks for reply, I found same solution on another blog, RowCount component resolved the issue.

Thanks

Abdul


Saturday, May 09, 2020 - 3:51:28 PM - Haroon Ashraf Back To Top

I have found the root cause of the problem you do not seem to be missing anything since this tip is related to the starting and ending time of the packages with regards to time difference (UTC vs GMT) part of logging and not focussed on number of records to be logged to keep it simple and easy to understand that's why you do not see (that part of the work) it in that detail even in the final output despite being present in the SSIS Packages built for this tip.

However, if you please do the steps below you can see the desired DestinationRowCount as well:

(1) Please double click DFT Run Staging Extract to see the Data Flow Task

(2) Please drag a RowCount component from the SSIS Toolbox and drop it in the middle of OLE_SRC Watch source component and OLE_DST Staging_Watch destination component.

(3) Then double click RowCount component and select User::RowCount variable

(4) Save the work and rerun the SSIS package

That's it.

Thank you.


Saturday, May 09, 2020 - 5:03:00 AM - Abdul Khan Back To Top

Thanks for the input, however issue remains same, data in table is updated, which assign 0 to the column DestinationRows, since variable has 0 value. When I assing default value of 5 to record it is updated with 5. I just wanted to ask about the missing part of storing row count value from package to variable RowCount, this may resolve the issue.

Thanks


Wednesday, May 06, 2020 - 4:38:15 PM - Haroon Ashraf Back To Top

Hi Abdul,

I am pleased to know that you have successfully implemented both parts of logging by following the tips.

However, this does seem to be a very small thing somewhere in your code or variable mapping in SSIS Package.

So, what I understand is that the LogId column is showing 0 after the logging runs successfully.

In that case please reset your environment which means to drop the table and create it again and then run the logging process by running the SSIS Package.

-- (1) Connect to WatchesV4DW database via SSMS or Azure Portal
 
-- (2) Drop existing log table
DROP TABLE DWLog 
 
---- (2) Create mini logging events table (part-2)
CREATE TABLE DWLog
(
LogId INT IDENTITY(1,1),
ProcessName VARCHAR(200),
PackageName VARCHAR(200),
PackageStartDate DATETIME2,
PackageEndDate DATETIME2,
DestinationRows INT
CONSTRAINT [PK_DWLog] PRIMARY KEY (LogId),
)			

As I suspect the Identity increment LogId INT IDENTITY(1,1) is either missing or incorrect and resetting it, is going to help fix this problem but please let me know if this works or not?

Thank you.


Wednesday, May 06, 2020 - 1:38:54 PM - Abdul Khan Back To Top

Hi

I followed all steps in both parts, all works fine, even the execution end time is updated, however row count value is updated from null to zero, looks like value is not copied in the variable. both variable is defined same size / type as in the part. 

Thanks


Tuesday, May 05, 2020 - 8:53:58 AM - Haroon Ashraf Back To Top

Thank you for your valued feedback.

Can you please tell me have you followed the first part of this tip and have you able to implement it successfully?

Secondly by seeing row count 0 do you mean the log table is empty as it is not logging any data or you meant something else?

Thank you


Monday, May 04, 2020 - 5:41:23 PM - Abdul Khan Back To Top

I followed all steps, row count of the in the log table is coming as 0, cross checked twice, cannot find where the mistake is, please suggest solution.

Thanks

Abdul



download


Recommended Reading

Create Custom SSIS Execution Log - Part 1

Implement a Slowly Changing Type 2 Dimension in SQL Server Integration Services - Part 1

Export images from a SQL Server Table to a Folder with SSIS

SQL Server Integration Services Flexible File System Task with Local Storage

Optimizing Type 2 Slowly Changing Dimensions in Integration Services - Part 2





get free sql tips
agree to terms


Learn more about SQL Server tools