SSIS 2008 R2 Logging - Recommended Options
Within a SQL Server Integration Services (SSIS) ETL, tasks are being performed around data being moved from A to B with transformations occurring in between. Detailed logging options can be configured.Â
In our environment, logging when tasks occur along with any errors, warnings, and failures works best. Logging all possible events is rarely needed and often leads to performance degradation. The mere act of logging requires resources after all (CPU, disk, memory).
I setup a sample 2008 R2 ETL with four Control Flow items executed sequentially. Artificial delays have been coded into most of the components. The first component, for example, is an Execute SQL Task that is setup to delay two seconds.
Since each delay is controlled, the goal is to enable configuration to confirm those delays in our logging table.
Here are the four Control Flow items. The last item emails the execution instance GUID to me, which is used to look-up the logging that has occurred.
The Data Flow Task delays for five seconds before piping one row of data to a Script Component Transformation, which delays for 35 seconds. That row is then written to a flat file on my laptop.
An "SSIS log provider for SQL Server" has been configured to write its information to a database on our development server. The package events that will be logged are:
Bad stuff happening: OnError, OnTaskFailed, OnWarning
Timing of stuff happening: OnPreExecute, OnPostExecute
I executed the ETL and got an email with its execution instance GUID upon completion:
Using that, here's the raw data in the execution log...
...and the query used to find it:
-- Execution Log: select l.id, l.event, l.source, l.sourceid, l.message, l.starttime, l.endtime, datediff(second, l.starttime, l.endtime) as row_duration -- not helpful from ETLExecutionLog.dbo.sysdtslog90 l where l.executionid = '4BD3B61F-AFD3-4A6A-9F89-D9845A695CBF' order by l.starttime
The result set is kinda useful and even better when aggregated using only the OnPreExecute and OnPostExecute events...
...as generated with this query:
-- Timing of Control Flow items: select l.source, min(l.starttime) as start_dts, max(l.endtime) as end_dts, datediff(second, min(l.starttime), max(l.endtime)) as source_duration_sec from ETLExecutionLog.dbo.sysdtslog90 l where l.executionid = '4BD3B61F-AFD3-4A6A-9F89-D9845A695CBF' and l.event in ('OnPreExecute','OnPostExecute') -- comment out if these events don't exist group by l.source order by 2
Much better! I can now identify how long each Control Flow item took to run. The entire package took 46 seconds and the expected amount of each delay I setup is actually what's being captured.
This is showing that the Data Flow Task, which took 40 seconds to finish its work, is the bottleneck. Knowing this fact is typically enough to continue investigation (e.g. manually open the ETL and play around with what happens in the DFT). Nearly all of our data flows are as simple as possible. Data is selected, transformed just a bit, and stored in a table.
Let's say you're ETL is typically more complicated than that. You may want to enable an additional level of logging for the DFT level.Â
More Logging, Second Run Instance
I've modified the package's logging configuration to capture the OnPipelineComponent time event for the DFT in question. The package has run and once again I've been emailed the execution instance GUID: 6664EBC7-3DF8-461E-AB81-2E2F20F67D14.
The logging data isn't as clean as before, but it's enough to identify that the Script Component transformation is the bottleneck taking 35 seconds to finish:
That result set was generated with a query similar to the first one given above:
select l.id, l.event, l.source, l.sourceid, l.message, l.starttime, l.endtime from ETLExecutionLog.dbo.sysdtslog90 l where l.executionid = '6664EBC7-3DF8-461E-AB81-2E2F20F67D14' and l.event like '%PipelineComponentTime%' order by l.message, l.starttime
In my environment at work, we've found it beneficial to enable package level logging for these and only these events:
Bad stuff happening: OnError, OnTaskFailed, OnWarning
Timing of stuff happening: OnPreExecute, OnPostExecute
Having information on these events is typically all that is needed to narrow your investigation efforts when addressing errors or bottlenecks. Basically, it points you in the right direction for where to go next.