Analyzing Report Execution Time

One of the reasons I was digging around to find out how many reports were being executed for each folder the other day was that there were some subscription issues at the client.  The goal was to get a break down of when reports were being executed and generally who’s reports they were.

With that information in hand the topic quickly shifted to which reports were taking the most resources on the Reporting Services instance.  There are a number of ways to go about this but for this case I wanted to know how long it took from the when the report was requested until it was delivered to the user.

Like in the last post, this information can be gleamed from the ExecutionLog table in the Report Server database.  There are five columns that I use to get execution time information:

  • TimeStart – Time that the report execution begins
  • TimeEnd – Time that the report execution completes
  • TimeDataRetrieval- Time spent running retrieving data from data sources
  • TimeProcessing – Time spent processing the report
  • TimeRendering – Time spent rendering the report in the requested format

Note: that the execution time for the report for TimeDataRetrieval, TimeProcessing, and TimeRendering does not equal the difference between TimeStart and TimeEnd.  This is because there are other operations performed while executing and returning reports that are not tracked.

As with the other script, this query also includes start and end dates.  Here is the script:

DECLARE @StartDate datetime
    ,@EndDate datetime
SELECT @StartDate = '1/1/2009'
    ,@EndDate = '12/31/2009'
    ,COUNT(*) as Executions
    ,CAST(AVG(DATEDIFF(ms, TimeStart, TimeEnd)*1.)AS decimal(12,2)) AS AverageExecutionTime
    ,CAST(SUM(el.TimeDataRetrieval)/(COUNT(*)*1.) AS decimal(12,2)) AS AverageTimeDataRetrieval
    ,CAST(SUM(el.TimeProcessing)/(COUNT(*)*1.) AS decimal(12,2)) AS AverageTimeProcessing
    ,CAST(SUM(el.TimeRendering)/(COUNT(*)*1.) AS decimal(12,2)) AS AverageTimeRendering
    ,CAST((SELECT ' Count = "' + CAST(COUNT(*) as varchar) + '"'
            + ' Value = "' + COALESCE(CAST(iel.Parameters as varchar(max)), '-NONE-') + '"'   as Parameters
        FROM dbo.ExecutionLog iel
        WHERE iel.TimeStart BETWEEN MIN(el.TimeStart) AND MAX(el.TimeStart)
        AND iel.ReportID = el.ReportID
        GROUP BY COALESCE(CAST(iel.Parameters as varchar(max)), '-NONE-')
        FOR XML PATH('')) as xml) as Parameters
FROM dbo.ExecutionLog el
    INNER JOIN dbo.Catalog c ON el.ReportID = c.ItemID
WHERE el.TimeStart BETWEEN @StartDate AND @EndDate
GROUP BY, c.Path, el.ReportID
ORDER BY SUM(el.TimeDataRetrieval) DESC

Running the script on my laptop shows the reports that have been executed.  As you can tell, I am a reporting fiend.  Take a look at the output below”:



Do note the last column.  This column has an XML document that summarizes all of the parameter variations that were used to with the report in the given timeframe with a count of the number of executions.  For my purposes, I looked at the reports that were executed most frequently.

When I clicked on the XML link in the first row, it opened the following document:

 Count = "1" Value = "ShowDescription=False&StartDate=01/01/2002 00:00:00&EndDate=12/31/2003 00:00:00"
 Count = "1" Value = "ShowDescription=False&StartDate=1/1/2002 12:00:00 AM&EndDate=12/31/2003 12:00:00 AM"
 Count = "1" Value = "ShowDescription=False&StartDate=1/15/2002 12:00:00 AM&EndDate=12/31/2003 12:00:00 AM"
 Count = "1" Value = "ShowDescription=False&StartDate=6/15/2002 12:00:00 AM&EndDate=12/31/2003 12:00:00 AM"


I’ve found that this query to be quite helpful in finding both the high execution time reports along with sample parameter strings that can be used to performance test the reports.