ExecutionLog - times

I am using the ExecutionLog to find longest running report occurences, and
some issues arise.
Firstly can anyone tell me what the 'TimeProcessing' column covers, as
sometimes this is large ie for my reports 25 seconds. I can understand the
others ie TimeDataRetrieval and TimeRendering. I'm more a db than dev
person, so may be missing something obvious here.
Also, adding up these 3 times in milliseconds I assume should give you the
difference between TimeStart and TimeEnd, but this often varies, by as much
as 50 seconds. Any comments on this one?
Thanks
CR.TimeDataRetrieval, TimeProcessing, and TimeRendering show the time in
milliseconds. The TimeProcessing portion describes how much time the
processing engine spends to "process" the data. This includes grouping,
sorting, filtering of data, generating the output-format independent report
layout, etc.
If a report has multiple data sources, the RS processing engine performs
data retrieval and data processing in parallel (multiple threads) for these
data sources. However, there is only one row per report execution in the
execution log. In this case we will merge the retrieval and processing times
from multiple threads and use it for the execution log. In this situation
the sum of TimeDataRetrieval + TimeProcessing + TimeRendering is very likely
different than EndTime - StartTime.
Does this explain what you see in the execution log?
--
This posting is provided "AS IS" with no warranties, and confers no rights.
"CR" <CR@.discussions.microsoft.com> wrote in message
news:3FAC5B1D-00E8-44ED-BFF3-6DCAE8DBBCC9@.microsoft.com...
>I am using the ExecutionLog to find longest running report occurences, and
> some issues arise.
> Firstly can anyone tell me what the 'TimeProcessing' column covers, as
> sometimes this is large ie for my reports 25 seconds. I can understand
> the
> others ie TimeDataRetrieval and TimeRendering. I'm more a db than dev
> person, so may be missing something obvious here.
> Also, adding up these 3 times in milliseconds I assume should give you the
> difference between TimeStart and TimeEnd, but this often varies, by as
> much
> as 50 seconds. Any comments on this one?
> Thanks
> CR.|||Thank you, this is very helpful.
Summing of the 3 times and comparing to the Start and End times: I think
you are saying that the 3 times added will be greater than the Start and End?
What I'm seeing is the opposite. It's occuring only on my most complicated
reports, never on the simple ones. There are times when the 3 times are all
0 (in seconds), but the Start-End is 72 seconds, and for other runs of the
same report with similar parameters one or more of the times are 0 and the
other times are 20sec +, with the Start-End difference still 40+ seconds, ie
20 seconds has been 'lost'.
I'm seeing this on most runs of the more complex reports, of which there are
4 that I track in detail. Any comments on this one?
Secondly, I was wondering which set of data ie 3 times or Start-End was more
reliable when determining how long reports run; from what you've said
Start-End is the one to use, so thanks.
"Robert Bruckner [MSFT]" wrote:
> TimeDataRetrieval, TimeProcessing, and TimeRendering show the time in
> milliseconds. The TimeProcessing portion describes how much time the
> processing engine spends to "process" the data. This includes grouping,
> sorting, filtering of data, generating the output-format independent report
> layout, etc.
> If a report has multiple data sources, the RS processing engine performs
> data retrieval and data processing in parallel (multiple threads) for these
> data sources. However, there is only one row per report execution in the
> execution log. In this case we will merge the retrieval and processing times
> from multiple threads and use it for the execution log. In this situation
> the sum of TimeDataRetrieval + TimeProcessing + TimeRendering is very likely
> different than EndTime - StartTime.
> Does this explain what you see in the execution log?
> --
> This posting is provided "AS IS" with no warranties, and confers no rights.
>
> "CR" <CR@.discussions.microsoft.com> wrote in message
> news:3FAC5B1D-00E8-44ED-BFF3-6DCAE8DBBCC9@.microsoft.com...
> >I am using the ExecutionLog to find longest running report occurences, and
> > some issues arise.
> >
> > Firstly can anyone tell me what the 'TimeProcessing' column covers, as
> > sometimes this is large ie for my reports 25 seconds. I can understand
> > the
> > others ie TimeDataRetrieval and TimeRendering. I'm more a db than dev
> > person, so may be missing something obvious here.
> >
> > Also, adding up these 3 times in milliseconds I assume should give you the
> > difference between TimeStart and TimeEnd, but this often varies, by as
> > much
> > as 50 seconds. Any comments on this one?
> >
> > Thanks
> > CR.
>
>|||I meant that for a report with just 1 data source the following is always
true:
(TimeDataRetrieval + TimeProcessing + TimeRendering) <= (EndTime -
StartTime)
For reports with multiple data sources, this condition is not always true
because of multi-threaded execution. If certain columns (TimeDataRetrieval
and/or TimeProcessing) are 0, this means that the report was processed and
rendered from the report server's cache. If both, TimeDataRetrieval and
TimeProcessing are 0, the report was rendered from a history snapshot or
execution snapshot without re-processing.
For reports with single data sources, TimeDataRetrieval, TimeProcessing, and
TimeRendering are very reliable. For multi-threaded executions of one report
you may want to look at StartTime and EndTime.
--
This posting is provided "AS IS" with no warranties, and confers no rights.
"CR" <CR@.discussions.microsoft.com> wrote in message
news:7C2A33E2-E17B-4072-95ED-BC38B34288ED@.microsoft.com...
> Thank you, this is very helpful.
> Summing of the 3 times and comparing to the Start and End times: I think
> you are saying that the 3 times added will be greater than the Start and
> End?
> What I'm seeing is the opposite. It's occuring only on my most
> complicated
> reports, never on the simple ones. There are times when the 3 times are
> all
> 0 (in seconds), but the Start-End is 72 seconds, and for other runs of the
> same report with similar parameters one or more of the times are 0 and the
> other times are 20sec +, with the Start-End difference still 40+ seconds,
> ie
> 20 seconds has been 'lost'.
> I'm seeing this on most runs of the more complex reports, of which there
> are
> 4 that I track in detail. Any comments on this one?
> Secondly, I was wondering which set of data ie 3 times or Start-End was
> more
> reliable when determining how long reports run; from what you've said
> Start-End is the one to use, so thanks.
> "Robert Bruckner [MSFT]" wrote:
>> TimeDataRetrieval, TimeProcessing, and TimeRendering show the time in
>> milliseconds. The TimeProcessing portion describes how much time the
>> processing engine spends to "process" the data. This includes grouping,
>> sorting, filtering of data, generating the output-format independent
>> report
>> layout, etc.
>> If a report has multiple data sources, the RS processing engine performs
>> data retrieval and data processing in parallel (multiple threads) for
>> these
>> data sources. However, there is only one row per report execution in the
>> execution log. In this case we will merge the retrieval and processing
>> times
>> from multiple threads and use it for the execution log. In this situation
>> the sum of TimeDataRetrieval + TimeProcessing + TimeRendering is very
>> likely
>> different than EndTime - StartTime.
>> Does this explain what you see in the execution log?
>> --
>> This posting is provided "AS IS" with no warranties, and confers no
>> rights.
>>
>> "CR" <CR@.discussions.microsoft.com> wrote in message
>> news:3FAC5B1D-00E8-44ED-BFF3-6DCAE8DBBCC9@.microsoft.com...
>> >I am using the ExecutionLog to find longest running report occurences,
>> >and
>> > some issues arise.
>> >
>> > Firstly can anyone tell me what the 'TimeProcessing' column covers, as
>> > sometimes this is large ie for my reports 25 seconds. I can understand
>> > the
>> > others ie TimeDataRetrieval and TimeRendering. I'm more a db than dev
>> > person, so may be missing something obvious here.
>> >
>> > Also, adding up these 3 times in milliseconds I assume should give you
>> > the
>> > difference between TimeStart and TimeEnd, but this often varies, by as
>> > much
>> > as 50 seconds. Any comments on this one?
>> >
>> > Thanks
>> > CR.
>>|||Clarification to my previous posting: I meant reports with just 1 dataset.
If reports have 1 data source, but multiple data sets and "use single
transaction" is not selected, the processing engine will still use
multi-threaded data retrieval and processing.
--
This posting is provided "AS IS" with no warranties, and confers no rights.
"Robert Bruckner [MSFT]" <robruc@.online.microsoft.com> wrote in message
news:uV22MX%23FFHA.1528@.TK2MSFTNGP09.phx.gbl...
>I meant that for a report with just 1 data source the following is always
>true:
> (TimeDataRetrieval + TimeProcessing + TimeRendering) <= (EndTime -
> StartTime)
> For reports with multiple data sources, this condition is not always true
> because of multi-threaded execution. If certain columns (TimeDataRetrieval
> and/or TimeProcessing) are 0, this means that the report was processed and
> rendered from the report server's cache. If both, TimeDataRetrieval and
> TimeProcessing are 0, the report was rendered from a history snapshot or
> execution snapshot without re-processing.
> For reports with single data sources, TimeDataRetrieval, TimeProcessing,
> and TimeRendering are very reliable. For multi-threaded executions of one
> report you may want to look at StartTime and EndTime.
> --
> This posting is provided "AS IS" with no warranties, and confers no
> rights.
>
> "CR" <CR@.discussions.microsoft.com> wrote in message
> news:7C2A33E2-E17B-4072-95ED-BC38B34288ED@.microsoft.com...
>> Thank you, this is very helpful.
>> Summing of the 3 times and comparing to the Start and End times: I think
>> you are saying that the 3 times added will be greater than the Start and
>> End?
>> What I'm seeing is the opposite. It's occuring only on my most
>> complicated
>> reports, never on the simple ones. There are times when the 3 times are
>> all
>> 0 (in seconds), but the Start-End is 72 seconds, and for other runs of
>> the
>> same report with similar parameters one or more of the times are 0 and
>> the
>> other times are 20sec +, with the Start-End difference still 40+ seconds,
>> ie
>> 20 seconds has been 'lost'.
>> I'm seeing this on most runs of the more complex reports, of which there
>> are
>> 4 that I track in detail. Any comments on this one?
>> Secondly, I was wondering which set of data ie 3 times or Start-End was
>> more
>> reliable when determining how long reports run; from what you've said
>> Start-End is the one to use, so thanks.
>> "Robert Bruckner [MSFT]" wrote:
>> TimeDataRetrieval, TimeProcessing, and TimeRendering show the time in
>> milliseconds. The TimeProcessing portion describes how much time the
>> processing engine spends to "process" the data. This includes grouping,
>> sorting, filtering of data, generating the output-format independent
>> report
>> layout, etc.
>> If a report has multiple data sources, the RS processing engine performs
>> data retrieval and data processing in parallel (multiple threads) for
>> these
>> data sources. However, there is only one row per report execution in the
>> execution log. In this case we will merge the retrieval and processing
>> times
>> from multiple threads and use it for the execution log. In this
>> situation
>> the sum of TimeDataRetrieval + TimeProcessing + TimeRendering is very
>> likely
>> different than EndTime - StartTime.
>> Does this explain what you see in the execution log?
>> --
>> This posting is provided "AS IS" with no warranties, and confers no
>> rights.
>>
>> "CR" <CR@.discussions.microsoft.com> wrote in message
>> news:3FAC5B1D-00E8-44ED-BFF3-6DCAE8DBBCC9@.microsoft.com...
>> >I am using the ExecutionLog to find longest running report occurences,
>> >and
>> > some issues arise.
>> >
>> > Firstly can anyone tell me what the 'TimeProcessing' column covers, as
>> > sometimes this is large ie for my reports 25 seconds. I can
>> > understand
>> > the
>> > others ie TimeDataRetrieval and TimeRendering. I'm more a db than dev
>> > person, so may be missing something obvious here.
>> >
>> > Also, adding up these 3 times in milliseconds I assume should give you
>> > the
>> > difference between TimeStart and TimeEnd, but this often varies, by as
>> > much
>> > as 50 seconds. Any comments on this one?
>> >
>> > Thanks
>> > CR.
>>
>|||Robert,
The reports with the Time summing issues have multiple datasets, up to 7 in
fact, and the ones with single datasets I am getting no summing issues at
all, as you have explained.
On the multi-dataset reports with Time summing issues, there is no cacheing
or snapshots on any of the reports (in fact I should set some up), and still
the 3 Time values can be all 0s, with a 72 second Start-End difference. I'm
thinking therefore that the merging algorithm for the 3 times is the
significant issue. BTW, from observation in my reports only, the 3 times are
always understated not overstated ie they always sum to less than Start-End.
Does this sound right to you?
Thanks for your help this is very useful. My interest in this is to reduce
report execution times, and I'm using the 3 times to pinpoint the bottlenecks
where possible.
"Robert Bruckner [MSFT]" wrote:
> Clarification to my previous posting: I meant reports with just 1 dataset.
> If reports have 1 data source, but multiple data sets and "use single
> transaction" is not selected, the processing engine will still use
> multi-threaded data retrieval and processing.
> --
> This posting is provided "AS IS" with no warranties, and confers no rights.
> "Robert Bruckner [MSFT]" <robruc@.online.microsoft.com> wrote in message
> news:uV22MX%23FFHA.1528@.TK2MSFTNGP09.phx.gbl...
> >I meant that for a report with just 1 data source the following is always
> >true:
> > (TimeDataRetrieval + TimeProcessing + TimeRendering) <= (EndTime -
> > StartTime)
> >
> > For reports with multiple data sources, this condition is not always true
> > because of multi-threaded execution. If certain columns (TimeDataRetrieval
> > and/or TimeProcessing) are 0, this means that the report was processed and
> > rendered from the report server's cache. If both, TimeDataRetrieval and
> > TimeProcessing are 0, the report was rendered from a history snapshot or
> > execution snapshot without re-processing.
> >
> > For reports with single data sources, TimeDataRetrieval, TimeProcessing,
> > and TimeRendering are very reliable. For multi-threaded executions of one
> > report you may want to look at StartTime and EndTime.
> >
> > --
> > This posting is provided "AS IS" with no warranties, and confers no
> > rights.
> >
> >
> > "CR" <CR@.discussions.microsoft.com> wrote in message
> > news:7C2A33E2-E17B-4072-95ED-BC38B34288ED@.microsoft.com...
> >> Thank you, this is very helpful.
> >>
> >> Summing of the 3 times and comparing to the Start and End times: I think
> >> you are saying that the 3 times added will be greater than the Start and
> >> End?
> >> What I'm seeing is the opposite. It's occuring only on my most
> >> complicated
> >> reports, never on the simple ones. There are times when the 3 times are
> >> all
> >> 0 (in seconds), but the Start-End is 72 seconds, and for other runs of
> >> the
> >> same report with similar parameters one or more of the times are 0 and
> >> the
> >> other times are 20sec +, with the Start-End difference still 40+ seconds,
> >> ie
> >> 20 seconds has been 'lost'.
> >>
> >> I'm seeing this on most runs of the more complex reports, of which there
> >> are
> >> 4 that I track in detail. Any comments on this one?
> >>
> >> Secondly, I was wondering which set of data ie 3 times or Start-End was
> >> more
> >> reliable when determining how long reports run; from what you've said
> >> Start-End is the one to use, so thanks.
> >>
> >> "Robert Bruckner [MSFT]" wrote:
> >>
> >> TimeDataRetrieval, TimeProcessing, and TimeRendering show the time in
> >> milliseconds. The TimeProcessing portion describes how much time the
> >> processing engine spends to "process" the data. This includes grouping,
> >> sorting, filtering of data, generating the output-format independent
> >> report
> >> layout, etc.
> >>
> >> If a report has multiple data sources, the RS processing engine performs
> >> data retrieval and data processing in parallel (multiple threads) for
> >> these
> >> data sources. However, there is only one row per report execution in the
> >> execution log. In this case we will merge the retrieval and processing
> >> times
> >> from multiple threads and use it for the execution log. In this
> >> situation
> >> the sum of TimeDataRetrieval + TimeProcessing + TimeRendering is very
> >> likely
> >> different than EndTime - StartTime.
> >>
> >> Does this explain what you see in the execution log?
> >>
> >> --
> >> This posting is provided "AS IS" with no warranties, and confers no
> >> rights.
> >>
> >>
> >>
> >> "CR" <CR@.discussions.microsoft.com> wrote in message
> >> news:3FAC5B1D-00E8-44ED-BFF3-6DCAE8DBBCC9@.microsoft.com...
> >> >I am using the ExecutionLog to find longest running report occurences,
> >> >and
> >> > some issues arise.
> >> >
> >> > Firstly can anyone tell me what the 'TimeProcessing' column covers, as
> >> > sometimes this is large ie for my reports 25 seconds. I can
> >> > understand
> >> > the
> >> > others ie TimeDataRetrieval and TimeRendering. I'm more a db than dev
> >> > person, so may be missing something obvious here.
> >> >
> >> > Also, adding up these 3 times in milliseconds I assume should give you
> >> > the
> >> > difference between TimeStart and TimeEnd, but this often varies, by as
> >> > much
> >> > as 50 seconds. Any comments on this one?
> >> >
> >> > Thanks
> >> > CR.
> >>
> >>
> >>
> >
> >
>
>