1

I have a database which is getting a lot of calls to the following procedure:

exec dbo.SM_SP_MAILEVENTNAMES 167260

In Profiler using the TSQL_Duration trace these calls show up as:

EventClass: RPC: Completed
Duration:   900 to 1500 ms
Reads:      8818 

Running the same query in Management Studio with Statistics I/O:

set statistics io on
exec dbo.SM_SP_MAILEVENTNAMES 167260

Runs instantaneously and has the following I/O output:

Table 'SM_MAIL_CONTACTS'. Scan count 0, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'SM_MAIL_EVENT_CONTACTS'. Scan count 13, logical reads 68, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'SM_MATTER_EVENTS'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

The query itself returns about 3 rows. Why the disparity in what I am seeing in Profiler and Management Studio?

1

1 Answer 1

2

The difference in logical reads leads me to believe that the two executions are getting different plans. This could be because:

You can see if there are two or more different plans for the procedure using something like this, which will also identify if this is caused by either (or both) of the two most likely factors for different plan choice:

SELECT p.plan_handle, p.usecounts, p.size_in_bytes, 
  set_options = MAX(CASE a.attribute WHEN N'set_options' THEN a.value END),
  dflt_schema = MAX(CASE a.attribute WHEN N'user_id'     THEN a.value END)
FROM sys.dm_exec_cached_plans AS p
CROSS APPLY sys.dm_exec_sql_text(p.plan_handle) AS t
CROSS APPLY sys.dm_exec_plan_attributes(p.plan_handle) AS a
WHERE t.objectid = OBJECT_ID(N'dbo.SM_SP_MAILEVENTNAMES')
AND a.attribute IN (N'user_id', N'set_options')
GROUP BY p.plan_handle, p.usecounts, p.size_in_bytes;
5
  • Thank you, the only schema in use on this database is "dbo". Nov 18, 2014 at 16:21
  • @Geoff you should still specify. Nov 18, 2014 at 16:26
  • and I did indeed edit the original post. Thank you for your editing of that and I will run your query as soon as I can. I appreciate all your help. Nov 18, 2014 at 19:57
  • Hi Aaron the results of the query that you supplied show two set options 251 for the slow query from the app and 4347 for the fast one run in management studio. Nov 19, 2014 at 12:50
  • @Geoff so that is the difference, and why you are getting different plans. You can try to defeat this by flushing those two plans or adding OPTION (RECOMPILE) to the query, or by going through the individual SET options and see which ones are different (I can't do the bin-unpacking in my head, sorry). Nov 19, 2014 at 13:14

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.