Today’s post is from Wee Hyong Tok – a Program Manager on the SSIS team based in Shanghai. It covers the PipelineComponentTime event, which was introduced in SQL Server 2008, and talks about how the event can be used in SQL Server Denali.
The PipelineComponentTime event is a very useful custom log entry used for tracking the time spent at each of the five major processing steps of a data flow component: Validate, PreExecute, ProcessInput, PrimeOutput, PostExecute. When the PipelineComponentTime event is enabled, Integration Services logs one message for each processing step performed by each component.
The PipelineComponentTime captures the wall-clock time for each of the phases. In the case of ProcessInput, the PipelineComponentTime might not be sufficient if SSIS developers want to find out the time in which the component spent doing “real work”. This is because ProcessInput can be invoked multiple times by the SSIS engine (i.e. whenever an upstream component sends the component a buffer). As a result, if one captures just the first entry time and the last exit time in which ProcessInput is invoked, it will be hard to compute the active time spent in ProcessInput only. See the diagram below which illustrates the difference between the total and active time.
The total time (i.e. PipelineComponentTime) is t1+t2+t3 . The active time spent in ProcessInput is t1+t3 .
In SQL Server Denali, SSIS developers are now able to obtain both the active and total time via the catalog,execution_component_phases view. This view is populated when the Logging Level is set to Performance or Verbose . The view provides information on the start and end time that are spent in each phase of a component. When a component’s ProcessInput is invoked multiple times, this shows up as multiple rows in the view.
The following T-SQL query snippet shows how to obtain the start and end time spent in each phase of a component.
FROM catalog.execution_component_phases
WHERE execution_id = @execution_id
ORDER BY task_name, subcomponent_name, execution_path
The following T-SQL query snippet can be used to find the active and total time for an execution.
SELECT task_name, subcomponent_name, execution_path, phase,
SUM(DATEDIFF(ms,start_time,end_time)) as active_time_ms,
DATEDIFF(ms,min(start_time), max(end_time)) as total_time_ms
FROM catalog.execution_component_phases
WHERE execution_id = @execution_id
GROUP BY task_name, subcomponent_name, execution_path, phase
ORDER BY task_name, subcomponent_name, execution_path, phase
More information