Sql-server – Slow SSRS Report in production

I wouldn't bother with using Profiler at this point. You're likely just exasperating the issue, since streaming that back through a UI is not exactly light on resources. If you want to trace, set up a server-side trace and inspect the results afterward.

But first, let's start simpler. When the procedure is running in its "stuck" state, look at the DMV sys.dm_exec_requests. You want to see what it is waiting on (wait_type, last_wait_type) and whether it is being blocked by another session (blocking_session_id). You can also see if certain SET settings (quoted_identifier, arithabort, etc.) are different for the session than they are for the plan (which you can get in a roundabout way from sys.dm_exec_plan_attributes) and for the stored procedure itself - some of which you can get using OBJECTPROPERTY().

For example, let's compare just a few settings for the procedure, the session and the plan. First, while the query is running forever (and assuming you know the spid; I'll assume here it is 67), check these values from sys.dm_exec_requests and sys.dm_exec_sessions:

SELECT [status], wait_type, last_wait_type, plan_handle, blocking_session_id
  FROM sys.dm_exec_requests 
  WHERE session_id = 67;

SELECT [quoted_identifier], [arithabort], [ansi_nulls], [date_format]
  FROM sys.dm_exec_sessions 
  WHERE session_id = 67;

Now, this might immediately tell you where to look for the problem : you may have a wait_type that indicates there is an I/O problem, or you might see that the session is being blocked - in which case you can investigate what that session (blocking_session_id) is doing.

If neither of those pieces of information are useful, let's move on to the plan. A common issue with plans is that they can be different depending on various SET options, and this can result in quite different performance for two different users or an application and SSMS.

The plan handle is going to be a big 0x00... varbinary value in the results above. You can copy and paste that into this query:

SELECT 
  [quoted_identifier] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        64 & CONVERT(INT, a.value) END = 64 THEN 1 ELSE 0 END),
  [arithabort] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        4096 & CONVERT(INT, a.value) END = 4096 THEN 1 ELSE 0 END),
  [ansi_nulls] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        32 & CONVERT(INT, a.value) END = 32 THEN 1 ELSE 0 END),
  [date_format] = MAX(CASE WHEN attribute = 'date_format' THEN 
        CONVERT(INT, a.value) END)
FROM sys.dm_exec_cached_plans AS p
CROSS APPLY sys.dm_exec_plan_attributes(p.plan_handle) AS a

WHERE p.plan_handle = 0x... --<-- *** put the plan handle here ***

AND a.attribute IN ('set_options', 'date_format');

And you can compare those results with the session values you pulled above, and also some of these properties are stored with the procedure itself:

SELECT OBJECTPROPERTY(OBJECT_ID('dbo.usp_query_procedure'), 'IsQuotedIdentOn');
SELECT OBJECTPROPERTY(OBJECT_ID('dbo.usp_query_procedure'), 'ExecIsQuotedIdentOn');

You can also repeat that query for any other plans you find for the same procedure, to see if there are in fact cases where the procedure is executed with different settings:

SELECT 
  p.plan_handle,
  [quoted_identifier] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        64 & CONVERT(INT, a.value) END = 64 THEN 1 ELSE 0 END),
  [arithabort] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        4096 & CONVERT(INT, a.value) END = 4096 THEN 1 ELSE 0 END),
  [ansi_nulls] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        32 & CONVERT(INT, a.value) END = 32 THEN 1 ELSE 0 END),
  [date_format] = MAX(CASE WHEN attribute = 'date_format' THEN 
        CONVERT(INT, a.value) END)
FROM sys.dm_exec_cached_plans AS p
CROSS APPLY sys.dm_exec_plan_attributes(p.plan_handle) AS a
INNER JOIN sys.dm_exec_procedure_stats AS s
ON p.plan_handle = s.plan_handle
AND s.[object_id] = OBJECT_ID('dbo.usp_query_procedure')
AND a.attribute IN ('set_options', 'date_format')
GROUP BY p.plan_handle; 

If you see more than one result, then check every column. Any columns where one plan shows a 1 and the other plan shows a 0 would be suspicious to me.

In the meantime you can read a few great posts about this and similar issues:

http://www.sommarskog.se/query-plan-mysteries.html

http://www.simple-talk.com/sql/t-sql-programming/dmvs-for-query-plan-metadata/

http://www.benjaminnevarez.com/2011/09/parameter-sniffing-and-plan-reuse-affecting-set-options/

And yes, sp_WhoIsActive will probably give you some insight into what is going on as well.

Based on past interactions, I'm pretty sure that you're at least on SQL Server 2008R2. You could try filtering on the output of an Extended Event session. Here's a basic one to get you started.

  CREATE EVENT SESSION query_check ON SERVER
    ADD EVENT sqlserver.sql_statement_starting(
        ACTION (sqlserver.database_id, sqlserver.sql_text)),
    ADD EVENT sqlserver.sql_statement_completed(
        ACTION (sqlserver.database_id, sqlserver.sql_text)),
    ADD EVENT sqlserver.sp_statement_starting(
        ACTION (sqlserver.database_id, sqlserver.sql_text)),
    ADD EVENT sqlserver.sp_statement_completed(
        ACTION (sqlserver.database_id, sqlserver.sql_text))
    ADD TARGET package0.asynchronous_file_target(SET filename=N'D:\temp\monitor.xel',max_file_size=(5),max_rollover_files=(4))
    --,ADD TARGET package0.ring_buffer(SET max_events_limit=(5000),max_memory=(4096))
    WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=120 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON);

You can start it like this:

ALTER EVENT SESSION query_check ON SERVER STATE=START;

Run your query a few times and then stop the event session:

ALTER EVENT SESSION query_check ON SERVER STATE=STOP;

Then you can query it like this:

SELECT  
    fired_event = event_data.value('(/event/@name)[1]','nvarchar(25)'),
    fired_event_time = event_data.value('(/event/@timestamp)[1]','datetime2(0)'),
    event_database_id = event_data.value('(/event/action[@name=''database_id''])[1]','int'),
    event_sql_text = event_data.value('(/event/action[@name=''sql_text''])[1]','nvarchar(max)')  
FROM (
        SELECT CAST(event_data AS XML) AS event_data
        FROM sys.fn_xe_file_target_read_file(N'D:\temp\monitor*.xel', 
                                            N'D:\temp\monitor*.xem', 
                                            NULL, NULL)
    ) events 

You can capture more data, you can choose what you'd like from here:

SELECT p.name AS package_name,
       o.name AS action_name,
       o.description
FROM sys.dm_xe_packages AS p
JOIN sys.dm_xe_objects AS o 
     ON p.guid = o.package_guid
WHERE (p.capabilities IS NULL OR p.capabilities & 1 = 0)
  AND (o.capabilities IS NULL OR o.capabilities & 1 = 0)
  AND o.object_type = 'action'

So if you wanted to capture login information, you'd modify your ACTIONs from

ACTION (sqlserver.database_id, sqlserver.sql_text)),

to

ACTION (sqlserver.database_id, sqlserver.sql_text, sqlserver.username)),

I'd actually recommend against filtering on the query text because it's expensive. Instead, I'd try to find the correct username. If you don't think this will work, then I'd filter based on the query text of the result XML file. In fact, only in SQL Server 2012 can you filter on the statement text anyway (it's called a predicate).

If you wanted to perhaps capture data from a specific username you'd add WHERE to each EVENT that you'd like to filter.

ADD EVENT sqlserver.sql_statement_starting(
    ACTION (sqlserver.database_id, sqlserver.sql_text)
    WHERE (sqlserver.username = N'{{ your username here }}')
)