PipeLineComponentTime calculating incorrectly?
Hi, I'm trying to find out exactly how much time each of my tasks did take. I'm using PipeLineComponentTime logging feature. And the numbers in the logs confuses me as they are very big. Here is the sample (these rows are for the same task in the same execution):
id event starttime endtime message
68 User:PipelineComponentTime 2012.08.14 09:38 2012.08.14 09:38 The component "Merge INNER JOIN 2" (27492) spent 0 milliseconds in Validate.
203 User:PipelineComponentTime 2012.08.14 09:38 2012.08.14 09:38 The component "Merge INNER JOIN 2" (27492) spent 16 milliseconds in Validate.
339 User:PipelineComponentTime 2012.08.14 09:38 2012.08.14 09:38 The component "Merge INNER JOIN 2" (27492) spent 16 milliseconds in Validate.
484 User:PipelineComponentTime 2012.08.14 09:38 2012.08.14 09:38 The component "Merge INNER JOIN 2" (27492) spent 15 milliseconds in PreExecute.
628 User:PipelineComponentTime 2012.08.14 09:58 2012.08.14 09:58 The component "Merge INNER JOIN 2" (27492) spent 0 milliseconds in PostExecute.
629 User:PipelineComponentTime 2012.08.14 09:58 2012.08.14 09:58 During last execution the pipeline suspended output "Merge Join Output" (27495) of component "Merge INNER JOIN 2" (27492) for 1148021 milliseconds to limit the number of in-memory buffers.
808 User:PipelineComponentTime 2012.08.14 09:58 2012.08.14 09:58 The component "Merge INNER JOIN 2" (27492) spent 1153375 milliseconds in ProcessInput.
887 User:PipelineComponentTime 2012.08.14 09:58 2012.08.14 09:58 The component "Merge INNER JOIN 2" (27492) spent 2894071 milliseconds in PrimeOutput filling buffers on output "Merge Join Output" (27495).
Now the whole package took 20 minutes (I have my own logging), also you can see the same 20 minutes in StartTime, Endtime columns (from 4th to 5th rows). But if I calculate by the milliseconds which are in the message - I get total of 67 minutes.
So the question is - how do I interpret those messages and do they have a meaning at all?
P.S. using SQL2008
August 14th, 2012 8:54am
I think your custom coding has an opportunity to improve.
You should only use the StartTime-EndTime elements of the PipeLineComponentTime
Arthur My Blog
Free Windows Admin Tool Kit Click here and download it now
August 14th, 2012 10:04am
I'm sorry , but I did not understand your response. It's not a custom code, it's a built in logging feature for SSIS. The results you see is from this built in package logging feature, not from my custom code.
August 14th, 2012 10:14am
OK, it was then my misunderstanding,
I think you cannot simply add the times up because some operations occur in parallel.Arthur My Blog
Free Windows Admin Tool Kit Click here and download it now
August 14th, 2012 10:26am
But even if I take only one of those lines, the last line, for example, PrimeOutput states that it took around 40 Minutes, which is still twice longer than the whole package...
August 14th, 2012 10:30am
Does the
2012.08.14 09:58
correspond to the time the package finished in your log?
Arthur My Blog
Free Windows Admin Tool Kit Click here and download it now
August 14th, 2012 10:38am
Does the
2012.08.14 09:58
correspond to the time the package finished in your log?
Arthur My Blog
August 14th, 2012 10:47am
Yes, somewhere about this time.
Free Windows Admin Tool Kit Click here and download it now
August 17th, 2012 3:35am