Analyzing Report Execution Time

Posted by & filed under , , , , .


fob_watch2
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'

 

SELECT c.name

    ,c.Path

    ,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-')

        ORDER BY COUNT(*) DESC

        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.name, 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":

ssrs2

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:

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

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.