Sql-server – Procedure showing different duration / reads in Profiler vs. SSMS

profilersql serverssms

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?

Best Answer

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;
Related Question