Monitoring SSRS Report Performance: Part 2

In part 1 of this series I discussed how I built a small VB.NET application that would show me what reports were currently running on our SQL 2008 Report Servers. In this post I’m going to show how to look at the performance of reports after they run.

Reporting services stores execution history in a table in the ReportServer database called ExecutionLogStorage. The ReportID can be joined to the Catalog table to get the name and path of the report. Report Services has a view called ExecutionLog2 prepared that you can use instead.

Most of the column names are self explanatory, and if you visit the links in the references section you’ll see a full description. The columns I mostly look at are

  • Parameters: Here I can see the parameters used for the report execution. This will let me rerun the report the same way the user did, helpful to determine where the problem is.
  • Status: This column shows if the user could view the report with no problems. I’m looking for rsSuccess. If the report was unsuccessful you’ll see why here. Depending on the Status I can look at the report server logs for more information.
  • TimeStart and Time End: These columns show me when the report ran and how long it took. I can see if the report execution happened when the server was under pressure or if it was the only report running at the time.
  • TimeDataRetrieval: This column shows the time, in milliseconds, that the report took to fetch the data. High values here may indicate the problem is with the report data source and not the report server. It’s also nice to compare times when the report has changed.
  • TimeProcessing and TimeRendering: How long did it take the report server to deliver the report to the user? Values here are in milliseconds.
  • ByteCount and RowCount: How big is the report? Bigger reports take longer to process.
  • AdditionalInfo:There’s information here that shows information related to the memory and paging of the report.

Here are two scripts I use to look at the ExecutionLog2 view. The first will show each report execution for the time range I provide. I usually run it once in the morning for a quick look and again when users report performance problems.

DECLARE @TimeStart DATETIME, @TimeEnd DATETIME
SET @TimeStart = '2011-10-24 06:00'
SET @TimeEnd = '2011-10-24 12:00'
SELECT ReportPath
       , UserName
       , [Status]
       , TimeStart
       , TimeEnd
       , DATEDIFF(ss,TimeStart,TimeEnd) AS ElapsedSec
       , TimeDataRetrieval /1000.00 AS TimeDataRetrieval
       , TimeProcessing /1000.00 AS TimeProcessing
       , TimeRendering /1000.00 AS TimeRendering
       , ByteCount
       , [RowCount]
       , ISNULL(AdditionalInfo.value('(/AdditionalInfo/ScalabilityTime)[0]', 'int'),0) AS PaginationScalabilityTime
       , ISNULL(AdditionalInfo.value('(/AdditionalInfo/ScalabilityTime)[1]', 'int'),0) AS ProcessingScalabilityTime
       , ISNULL(AdditionalInfo.value('(/AdditionalInfo/ScalabilityTime)[0]', 'int'),0) +
         ISNULL(AdditionalInfo.value('(/AdditionalInfo/ScalabilityTime)[1]', 'int'),0) AS TotalScalabilityTime
       , ISNULL(AdditionalInfo.value('(/AdditionalInfo/EstimatedMemoryUsageKB/Pagination)[1]', 'bigint'),0) AS PaginationEstimatedMemUsageKB
       , ISNULL(AdditionalInfo.value('(/AdditionalInfo/EstimatedMemoryUsageKB/Processing)[1]', 'bigint'),0) AS ProcessingEstimatedMemUsageKB
       , ISNULL(AdditionalInfo.value('(/AdditionalInfo/EstimatedMemoryUsageKB/Pagination)[1]', 'bigint'),0) +
         ISNULL(AdditionalInfo.value('(/AdditionalInfo/EstimatedMemoryUsageKB/Processing)[1]', 'bigint'),0) AS TotalEstimatedMemUsageKB
FROM ReportServer.dbo.ExecutionLog2
WHERE TimeStart BETWEEN @TimeStart AND @TimeEnd
ORDER BY TimeStart

The second script is similar to the first except that it show report averages for the desired time frame. I usually run this once a month to get a baseline, then again at certain high volume times.

DECLARE @TimeStart DATETIME, @TimeEnd DATETIME

SET @TimeStart = '2011-09-01 00:00' 
SET @TimeEnd = '2011-10-01 00:00' 

SELECT
      ReportPath
    , COUNT(ExecutionId) AS NumReports
    , AVG(DATEDIFF(ss,TimeStart,TimeEnd)) AS AvgElapsedSec
    , AVG(TimeDataRetrieval /1000.00) AS AvgTimeDataRetrieval
    , AVG(TimeProcessing /1000.00) AS AvgTimeProcessing
    , AVG(TimeRendering /1000.00) AS AvgTimeRendering
    , AVG(ByteCount) AS AvgByteCount
    , AVG([RowCount]) AS AvgRowCount
    , AVG(ISNULL(AdditionalInfo.value('(/AdditionalInfo/ScalabilityTime)[0]', 'int'),0)) AS AvgPaginationScalabilityTime
    , AVG(ISNULL(AdditionalInfo.value('(/AdditionalInfo/ScalabilityTime)[1]', 'int'),0)) AS AvgProcessingScalabilityTime
    , AVG(ISNULL(AdditionalInfo.value('(/AdditionalInfo/EstimatedMemoryUsageKB/Pagination)[1]', 'bigint'),0)) A AS AvgPaginationEstimatedMemUsageKB
    , AVG(ISNULL(AdditionalInfo.value('(/AdditionalInfo/EstimatedMemoryUsageKB/Processing)[1]', 'bigint'),0)) AS AvgProcessingEstimatedMemUsageKB
 FROM ReportServer.dbo.ExecutionLog2
 WHERE TimeStart BETWEEN @TimeStart AND @TimeEnd
 GROUP BY ReportPath

I’ll have one final post where I look at report history with SSIS and SSAS.

Reference:

Robert Bruckner has a great blog on Report Server performance. This post is a great description of the ExecutionLog2 view.

ExecutionLog2 View – Analyzing and Optimizing Reports

p5rn7vb