0

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?

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;
  • Thank you, the only schema in use on this database is "dbo". – Geoff Bowden Nov 18 '14 at 16:21
  • @Geoff you should still specify. – Aaron Bertrand Nov 18 '14 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. – Geoff Bowden Nov 18 '14 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. – Geoff Bowden Nov 19 '14 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). – Aaron Bertrand Nov 19 '14 at 13:14

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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