| Groups | Blog | Home |
sql server reporting services : ExecutionLog - times
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
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. [quoted text, click to view] "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. [quoted text, click to view] "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. [quoted text, click to view] "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. [quoted text, click to view] "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. [quoted text, click to view] "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. > >>> > >>> > >>> > > > > > >
Don't see what you're looking for? Try a search.
|
June 2004
July 2004
August 2004
September 2004
October 2004
November 2004
December 2004
January 2005
February 2005
March 2005
April 2005
May 2005
June 2005
July 2005
August 2005
September 2005
October 2005
November 2005
December 2005
January 2006
February 2006
March 2006
April 2006
May 2006
June 2006
July 2006
August 2006
September 2006
October 2006
November 2006
December 2006
January 2007
February 2007
March 2007
April 2007
May 2007
June 2007
July 2007
August 2007
September 2007
October 2007
November 2007
| home · blog · groups | Questions? Comments? Contact the dn |