Flaw in dm_exec_procedure_stats?

Question

I am either off in my thinking or I don't understand the documentation. Just for clarity, the documentation on this management view uses the phrase "since it was last compiled" but does not clarify if that is the same as cached time. My ultimate goal is to retire an undocumented and outmoded database. I have already dealt with external dependencies to tables in the database and now I working with procedures and functions. I thought I could use this view [dm_exec_proedure_stats] to help discover what is being used and modify any callers. One of the procedures, a trivial one that returns output samples for all the different datetime convert constants, seems to be called thousands of times a day. I came to this conclusion using this code:

SELECT    DB_NAME()                     as DBName
        , oo.[Name]                     as ProcedureName    
        , SCHEMA_NAME(oo.schema_id)     as SchemaName       
        , sm.is_recompiled              as isRecompiled     
        , sp.modify_date                as Modify_date      
        , st.cached_time                as cached_time      
        , st.last_execution_time        as Last_exec_Time   
        , st.execution_count            as execution_ct     
        , st.total_elapsed_time         as TotExecTime      
FROM sys.sql_modules sm
        LEFT JOIN sys.objects oo
            on oo.object_id = sm.object_id
        LEFT JOIN Sys.procedures sp
            on sp.object_id = sm.object_id
        LEFT JOIN sys.dm_exec_procedure_stats st
            on st.object_id = sm.object_id
WHERE NOT oo.type IN ('tr','v','fn', 'tf', 'if')

When I ran a trace, which I am admittedly rusty at, it would not show any activity. To try and resolve this, I added the following code to the opening of the stored procedure which inserts every execution into a logging table.

INSERT INTO IT_SERVICE.dbo.DBA_ProcTrace
  ( ProcName, HostName, ProgramName, nt_domain, nt_userName, net_address, loginName, ProcSpid)
SELECT Object_name(@@PROCID), Hostname, program_name, nt_domain, nt_username, net_address, loginame, spid FROM Master.dbo.sysprocesses where spid = @@SPID

I then ran the data collection query [first above] which yielded this result (isolated to the proc of interest)

DBName  ProcedureName               SchemaName  isRecompiled    Modify_date             cached_time             Last_exec_Time          execution_ct    TotExecTime
@dbn    usp_ADMIN_Show_DateFormats  dbo         0               2023-08-23 09:50:28.420 2023-08-23 09:49:14.357 2023-08-23 10:17:43.797 168             172036

Then I executed the first query a half an hour later I get this result.

DBName  ProcedureName               SchemaName  isRecompiled    Modify_date             cached_time             Last_exec_Time          execution_ct    TotExecTime
DW_TBEI usp_ADMIN_Show_DateFormats  dbo         0               2023-08-23 09:50:28.420 2023-08-23 09:49:14.357 2023-08-23 10:41:32.130 333             280012

Perhaps my understanding of execution count is overly simplistic but I would have expected a query of my logging table to have 165 records for this procedure (333-168). To my surprise there is none. This remained the pattern through to now. The execution count keeps increasing however there are no entries in the logging table.

Can anyone tell me where i have failed logically or mechanically? Backing up to what my original purpose was, I am looking for the least invasive way of discovering which procedures are used with the bonus of capturing the caller in some fashion.

EDIT It seemed useful to Restate the query I mentioned in my question Incorporating the corrections from @MartinSmith.

SELECT    DB_NAME()                     as DBName
        , oo.[Name]                     as ProcedureName    
        , SCHEMA_NAME(oo.schema_id)     as SchemaName       
        , sm.is_recompiled              as isRecompiled     
        , sp.modify_date                as Modify_date      
        , st.cached_time                as cached_time      
        , st.last_execution_time        as Last_exec_Time   
        , st.execution_count            as execution_ct     
        , st.total_elapsed_time         as TotExecTime  
FROM sys.sql_modules sm
        LEFT JOIN sys.objects oo
            on oo.object_id = sm.object_id
        LEFT JOIN Sys.procedures sp
            on sp.object_id = sm.object_id
        LEFT JOIN sys.dm_exec_procedure_stats st
            on st.object_id = sm.object_id
                and st.database_id = DB_ID(DB_NAME())
WHERE NOT oo.type IN ('tr','v','fn', 'tf', 'if')
        AND NOT cached_time IS NULL

Would Maintenance plans be a better way to go. They seem serviceable but I have zero experience with them for this kind of analysis. — Paul Wichtendahl, Aug 23 '23 at 16:41
it probably means that if a procedure is recompiled, then the stats are wiped out for previous "versions" of the procedure. I wouldn't trust this view. Trace should work, but procedures has own "event type" SPCompleted or something like that — siggemannen, Aug 23 '23 at 16:44
@siggeman would you use a Maintenance plan or just an on-going trace for SPcomplete events in the profiler. I suppose another option would be to insert the code for logging above and add an "Instead of" trigger to record discrete users and sources. Still I wonder why the execution count exists if it is unreliable. It must mean something different than what I understand from "The number of times that the stored procedure has been executed since it was last compiled." [that is per the MS documentation] — Paul Wichtendahl, Aug 23 '23 at 16:53
What i mean is that recompilation can occur in a lot of events and times, so i wouldn't trust it if i wanted to know if procedure X is used or not :) Because a small flick of butterfly wings, and the statistics is gone. I guess you mean "extended events", not maintenance plans? I'm a bit old school, so i use trace, but i think extended events should work too. But if you have access to procedure itself, a logger is probably absolute best, then you will definitely know and it won't affect performance which trace might do — siggemannen, Aug 23 '23 at 17:02
I wouldn't expect that it is making up procedure executions that don't exist. Is your insert to the log table maybe encountering and error? — Martin Smith, Aug 23 '23 at 17:02
Checked that by calling it in a couple of different scenarios: Tested using: SSMS, Calling it by Exec from another procedure (same DB), calling it by exec in a procedure (differnt DB), in a Function, in a view and powershell from a different server. In all cases the procedure logged the event correctly. — Paul Wichtendahl, Aug 23 '23 at 17:05

Martin Smith · Answer 1 · 2023-08-23T17:45:56.287

Can anyone tell me where I have failed logically or mechanically?

You are missing any predicate on database_id

Try

LEFT JOIN sys.dm_exec_procedure_stats st on st.object_id = sm.object_id 
                                         and st.database_id = db_id()

So you only see results relevant to the database of interest.

Given that the logging to a table shows no procedure executions then likely you have a different object in a different database with the same object_id as usp_ADMIN_Show_DateFormats and this is explaining your "phantom" additional executions.

object_id in different databases are far from unique because different databases will inherit from the same model database and the mechanism for generating the "next" object_id is just to add 16000057 to the preceding one and wrap around on overflow so it is very likely to end up with common object_id across different databases all going around in the same cycle.

The absence of anything in sys.dm_exec_procedure_stats doesn't prove that the stored proc isn't being called as it is dependent on what is available in the cache but the above should avoid spurious false positives!

I came to write my own answer but @MartinSmith beat me to it. A bit of a "doh" on my part. Thank you Mr Smith. I got there by going deeper on the cached plans *dm_exec_cached_plans* and *dm_exec_sql_text* and when I re-ran the procedure I got multiple records for the procedure I was investigating. Then I used the SQL text to find the object (in this case ReportServer DB) i noted they had matching object_ids. Thanks again — Paul Wichtendahl, Aug 23 '23 at 18:13

Flaw in dm_exec_procedure_stats?

1 Answers1