Processing Time

Hi,

I am verifying my reports processing time. I get the information from the Reporting Service DB - [ExecutionLogs] table. I have the following information:

[TimeEnd] – time that reports generation ends.

[TimeStart] - time that reports generation starts.

[TimeDataRetrieval] - amount of time spent running the data sources.

[TimeProcessing] - time spent processing the report.

[TimeRendering] - time spent generating the output format.

If this information is correct the following statement should be true:

([TimeEnd] - [TimeStart]) = ([TimeDataRetrieval] + [TimeProcessing] + [TimeRendering])

But it isn't, ([TimeEnd] - [TimeStart]) is always bigger then ([TimeDataRetrieval] + [TimeProcessing] + [TimeRendering]).

Why does this happen?

Regards,

Rodrigo

That's interesting. I've never looked to check that. Are you seeing a big difference? how much is it a % of total execution time?

I suspect that TimeDataRetrieval, TimeProcessing, TimeRendering are each recorded by the subsystem resposible for each of those. I would expect there to be a small amount of overhead for the engine to do it's stuff and transition between the various phases between start and end.

|||

I have the following results for different reports:

End-Start

(ms)

Sum

(ms)

%

5030 3717 73,8966203 17437 12009 68,870792 5047 3374 66,851595 4733 3142 66,3849567 23170 15348 66,2408287 4780 3134 65,5648536 15750 10129 64,3111111 13017 7849 60,2980718 11153 6548 58,7106608 13170 7660 58,1624905 8830 5119 57,9728199

The first column is ([TimeEnd] - [TimeStart])

The second column is ([TimeDataRetrieval] + [TimeProcessing] + [TimeRendering])

How can i find the cause of this difference ?

Regards,

Rodrigo

|||

The difference is consistently large, too large. From your observations i.e. looking at the screen with a stopwatch, which is the "more correct" value?

|||

Do the reports have multiple datasets?

If multiple datasets are present and transactions are not used, SSRS will execute dataset queries in parallel. However, since there is only one data retrieval value in the execution log, it will pick the time of the longest data retrieval thread.

In addition, time data retrieval + processing + rendering does not cover all the time between the start and the end time of the request. Generally however, the other operations performed should just be small fraction compared to ([TimeDataRetrieval] + [TimeProcessing] + [TimeRendering]).

-- Robert