Flaw in dm_exec_procedure_stats?

259 Views Asked by At

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

1

There are 1 best solutions below

1
On

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!