November 20, 2015 at 10:50 am
We recently upgraded from SSRS 2005 to SSRS 2012. I've discovered that two of the views in the ReportServer db (ExecutionLog2, ExecutionLog3) contain a cool xml-based field called AdditionalInfo.
What particularly interests me about the field AdditionalInfo is that it records the data retrieval times for all datasets for a given report. This is awesome, but I'd like to query this field so that I can analyze the performances by dataset.
We have one particular report that contains 18 datasets, all stored procedure based, that needs to be studied for performance reasons, especially. Every now and then this particular report gets sluggish, inexplicably. (BTW, we've guarded against parameter sniffing, already, so I'm fairly certain param sniffing isn't the issue.)
Does anyone have a query they can share that splits out the nodes from the field AdditionalInfo? I'm particularly interested in records from ExecutionLog2 where Format='RPL' and ReportAction = 'Render'. By querying the AdditionalInfo field for a specific report over a period of time, I should be able to identify which datasets/stored-procs are potentially suspect of poor performance.
As a side note, I saved off the AdditionalInfo xml for one report record, and then opened the xml file in Excel. Excel easily converted the xml into a nice table structure with the following fields:
ProcessingEngine
Pagination
Processing
Pagination2
Processing3
SQL
ConnectionOpenTime
Name
RowsRead
TotalTimeDataRetrieval
ExecuteReaderTime
Lastly, I can see that TotalTimeDataRetrieval and ExecuteReaderTime are measured in milliseconds, but what unit of measure is ConnectionOpenTime?
Thanks,
Pete
November 20, 2015 at 12:10 pm
We have one particular report that contains 18 datasets, all stored procedure based, that needs to be studied for performance reasons, especially. Every now and then this particular report gets sluggish, inexplicably.
I would suggest running just the stored procedures, one at a time, to get an idea of which one is slowing you down. If you don't know what parameters values are being passed run a SQL Trace to capture that.
(BTW, we've guarded against parameter sniffing, already, so I'm fairly certain param sniffing isn't the issue.)
More important is that you determine which stored proc is slowing you down first. Parameter sniffing can be complicated. Once you identify which stored proc is slowing you down (if it is one of the stored procs) then should look at the query plan to see if you are experiencing parameter sniffing before you rule that in/out. If you can't figure it out post it here and someone will help you. A lot of things can cause parameter sniffing, there are several different methods to prevent parameter sniffing each with different pros/cons, there's even more things can cause a stored proc to be slow.
Does anyone have a query they can share that splits out the nodes from the field AdditionalInfo? I'm particularly interested in records from ExecutionLog2 where Format='RPL' and ReportAction = 'Render'. By querying the AdditionalInfo field for a specific report over a period of time...
I have never been in there (it's cool you posted this because it give me some ideas on how to identify a problem I'm dealing with)... here's a couple examples I cooked up quickly and added some notes; they should get you started.
SELECT
-- add/remove columns as needed.
InstanceName,
ReportPath,
UserName,
ExecutionId,
RequestType,
TimeStart,
TimeEnd,
--additionalinfo,
EstimatedMemoryPagination_KB =
ISNULL(ai.value('(EstimatedMemoryUsageKB/Pagination/text())[1]', 'int'),0),
EstimatedMemoryProcessing_KB =
ISNULL(ai.value('(EstimatedMemoryUsageKB/Processing/text())[1]', 'int'),0)
--Processing
FROM ExecutionLog2
CROSS APPLY additionalinfo.nodes('AdditionalInfo') A(ai)
WHERE Format = 'RPL' AND ReportAction = 'Render'
GO
-- make this a subquery and join back to ExecutionLog2 as needed
SELECT
-- since this is a one-to-many query let's add an identifier so we can group them
grouper = DENSE_RANK() OVER (ORDER BY TimeStart),
ExecutionId,
/*
-- add/remove columns as needed.
InstanceName,
ReportPath,
UserName,
ExecutionId,
RequestType,
TimeStart,
TimeEnd,
*/
-- ai.value('(ConnectionOpenTime/text())[1]','int')
ConnectionOpenTime = ai.value('(ConnectionOpenTime)[1]','int'),
DataSet = ai.value('(DataSets/DataSet/Name/text())[1]','varchar(200)'),
RowsRead = ai.value('(DataSets/DataSet/RowsRead/text())[1]','int'),
TotalTimeDataRetrieval = ai.value('(DataSets/DataSet/TotalTimeDataRetrieval/text())[1]','int')
FROM ExecutionLog2
CROSS APPLY additionalinfo.nodes('AdditionalInfo/Connections/Connection') A(ai)
WHERE Format = 'RPL' AND ReportAction = 'Render'
ORDER BY grouper
-- Itzik Ben-Gan 2001
November 23, 2015 at 1:34 pm
Alan:
Thanks for your reply!
Your SQL query is exactly what I was needing. Glad to hear that my post is of use to you as well.
As for your suggestions, I've already been running the stored procs individually attempting to assess which ones are slower than others. I'll keep analyzing query performance within the report, especially with your handy-dandy query in my toolkit now.
But, it seems there may actually be a "ghost in the machine". My colleagues and I are beginning to suspect that the team that setup the server may not have it configured optimally (hardware-wise, memory allocation, virtual-machine config...). We're seeing other issues with the server, not just inexplicable reporting performance lag, but also with data loading being impacted and network connectivity to other data sources failing.
Interestingly, this morning the "problem" report is now back to performing at blazing sub-1 second data-retrieval rates -- average time to retrieve the report data is .53 second! The only thing that changed on our end was that 65 million records were added to the data warehouse over the weekend. Doesn't make sense that more data would improve performance, does it?
So, for the time being, I'll keep monitoring the reports.
Thanks for your assistance,
Pete
Viewing 3 posts - 1 through 2 (of 2 total)
You must be logged in to reply to this topic. Login to reply