Wednesday, May 16, 2012

How to Display Report Execution Time in SSRS (milliseconds)

How to Display Report Execution Time in SQL Server Reporting Services 2008 R2
So there are other articles out there but I was looking to display in milliseconds the execution time it took for a particular report (which searches for results matching the submitted parameter) to run.

Lifted from Dattatray Sindol's blog
Other sites have this solution as well so who copied off who is not my concern as this is not the solution to our problem. This is the solution that I initially used but my end-users were asking why is it always 0 seconds. This was because we were using the following MDX statement which had seconds as its smallest denominator:
="Execution Time: " +
CStr(System.DateTime.Now.Subtract(Globals!ExecutionTime).Hours) + " hour(s)" + " , " +
CStr(System.DateTime.Now.Subtract(Globals!ExecutionTime).Minutes) + " minute(s)" + ", " +
CStr(System.DateTime.Now.Subtract(Globals!ExecutionTime).Seconds) + " second(s)"

// yields
// 0 hour(s), 1 minute(s), 2 second(s)
This isn't what I want... It wasn't accurate enough and always saying 0 seconds was just confusing the end-user...

Workaround #1
Although I'm convinced of a solution considering the ReportServer database will be able to tell you how many milliseconds it took for a report to execute... I decided to do a database level calculation using two datasets:
-- Oracle 10g: DataSet1 -- your normal dataset query with an added field (ReportStartTime)
SELECT
	field1,
	field2,
	TO_CHAR(systimestamp, 'HH24:MI:SS.FF6') AS ReportStartTime
FROM
	...
Then add another dataset (using the same data source if you like):
-- Oracle 10g: DataSet2 -- a quick dataset following the first (started before the first ends? hope not)
SELECT
	TO_CHAR(systimestamp, 'HH24:MI:SS.FF6') AS ReportEndTime
FROM
	DUAL
This may be just the time recorded that it took for the query which is somewhat the same thing for us as SSRS performance is always rubbish anyway. Here's a breakdown of the MDX expressions and how I tweaked each one to return the final result:
-- to get just the time value
=(
	CDate(Last(Fields!REPORTENDTIME.Value, "Dataset2"))
	-
	CDate(First(Fields!REPORTSTARTTIME.Value, "Dataset1"))
)
// yields 
// 00:00:02.1543570


-- problems with adding a string to it? CStr will not work, use .ToString
="Time Taken: " 
& (
	CDate(Last(Fields!REPORTENDTIME.Value, "Dataset2"))
	-
	CDate(First(Fields!REPORTSTARTTIME.Value, "Dataset1"))
).ToString & " second(s)"
// yields 
// Time Taken: 00:00:02.15443570 second(s)


-- What if the report actually took more than a minute... more than an hour
="Time Taken: " & (
(Mid(
	CStr(
		(
		CDate(Last(Fields!REPORTENDTIME.Value, "Dataset2"))
		-
		CDate(First(Fields!REPORTSTARTTIME.Value, "Dataset1"))
		).ToString
	), 1, 2
)*3600) + 
(Mid(
	CStr(
		(
		CDate(Last(Fields!REPORTENDTIME.Value, "Dataset2"))
		-
		CDate(First(Fields!REPORTSTARTTIME.Value, "Dataset1"))
		).ToString
	), 4, 2
)*60)
+ Mid(
	CStr(
		(
		CDate(Last(Fields!REPORTENDTIME.Value, "Dataset2"))
		-
		CDate(First(Fields!REPORTSTARTTIME.Value, "Dataset1"))
		).ToString
	), 7, Len(
		CStr(
			(
			CDate(Last(Fields!REPORTENDTIME.Value, "Dataset2"))
			-
			CDate(First(Fields!REPORTSTARTTIME.Value, "Dataset1"))
			).ToString
		)
	)
)) & " second(s)"

// yields 
// Time Taken: 2.15443570 second(s) 
// I don't have a report that takes over an hour to process but in theory this should accommodate it.


Problem #1
If zero rows are returned from the search, then there is no REPORTSTARTTIME. There are two options here:
  1. Create another dataset (would have to be the first dataset to load so you would need delete your current datasets then add them in the order you want them to load) to get the timestamp of when the queries started.
  2. IIF your result row count, if it's zero, just display blank, else, do the rest of the query. Blank out the textbox basically (execution time is kinda irrelevant when you get 0 matches)
We went with option 2.

Check this result - Possibly from the Reporting Server ExecutionLog?
Using the ReportServer Execution Logs, we can determine if this is correct
SELECT TOP 1
	c.Name, 
	e.TimeStart, 
	e.TimeDataRetrieval + e.TimeProcessing + e.TimeRendering AS TotalTime 
FROM
	[ExecutionLog] e
	INNER JOIN [Catalog] c ON c.ItemID=e.ReportID
WHERE c.Name='My Amazing Report'  -- just change the value here to the name of your report
ORDER BY e.TimeStart DESC
  1. Deploy the report to the SSRS
  2. Run the report from MS Internet Explorer
  3. Check results using Microsoft SQL Server Management Studio (SSMS)

My test results showed that in fact my time was closer to the "TimeProcessing" field of the ReportServer database, but good enough for us.

Add comment

Please note: all comments are reviewed before being published.


Security code
Refresh

Member Login

Joes Latest Members

A huge WELCOME goes to today's newest members:

  • infonat
Member Signups (Activated)
BeforeCurrentTrend
Day21=
Week105ê
Month11224ê
Year2,265612ê

Member Stats
54 guests are currently online.
1,178 members are still deciding.
There are 5,935 members in total.

Latest Comments

Paypal Donations

Want to support my work? Any donation is a blessing :c)