How to Display Report Execution Time in SSRS (milliseconds)

: Joel Lipman; SQL Server Reporting Services; 17 November 2011; Hits: 36346

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:

copy raw

="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)

="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:

copy raw

-- 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
	...

-- 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):

copy raw

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

-- 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:

copy raw

-- 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.

-- 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:

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.
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

copy raw

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

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