I am monitoring stored procedure executions, mainly the execution times and the CPU usage, using sys.dm_exec_query_stats in the script below.
SET NOCOUNT ON; declare @lastex datetime select @lastex = max(datestamp) from tablebackups.[dbo].[_dm_exec_query_stats] --Get proc counts since the starting point table creation insert into DBA.dbo.SPStats SELECT bcp.datestamp as StartTime ,getdate() as EndTime ,@@Servername as 'Server' ,isnull(DB_NAME(st.dbid),'') DBName ,isnull(OBJECT_SChEMA_NAME(st.objectid,st.dbid),'') [Schema] ,isnull(OBJECT_NAME(st.objectid,dbid),'') StoredProcedure ,max(cp.usecounts)-max(bcp.usecounts) as Execution_count ,--case --when sum(qs.total_worker_time)-sum(bqs.total_worker_time) < 0 -- then (9223372036854775807 - sum(convert(bigint,bqs.total_worker_time))+sum(convert(bigint,qs.total_worker_time))) --else sum(qs.total_worker_time)-sum(bqs.total_worker_time) -- end AS 'total_cpu_time' ,case max(cp.usecounts)-max(bcp.usecounts) when 0 then NULL else (sum(qs.total_worker_time)-sum(bqs.total_worker_time))/(max(cp.usecounts)-max(bcp.usecounts)) END as 'CPU_Per_execution' ,cast(convert(float,(max(cp.usecounts)-max(bcp.usecounts)))/convert(float,(datediff(s,bcp.DateStamp,getdate()))) as Numeric(18,3)) as 'Executions_Per_Second' ,sum(qs.Total_Logical_Reads)-sum(bqs.Total_Logical_Reads) as Total_Logical_Reads ,(sum(qs.Total_Logical_Reads)-sum(bqs.Total_Logical_Reads))/datediff(s,bcp.DateStamp,getdate()) as Total_Logical_Reads_per_sec ,sum(qs.Total_Logical_Writes)-sum(bqs.Total_Logical_Writes) as Total_Logical_Writes ,(sum(qs.Total_Logical_Writes)-sum(bqs.Total_Logical_Writes))/datediff(s,bcp.DateStamp,getdate()) as Total_Logical_Writes_per_sec ,datediff(n,bcp.DateStamp,getdate()) as 'Elapsed Time (m)' FROM sys.dm_exec_cached_plans cp inner join tablebackups.dbo._dm_exec_cached_plans bcp on cp.plan_handle = bcp.Plan_handle join sys.dm_exec_query_stats qs on cp.plan_handle = qs.plan_handle inner join tablebackups.dbo._dm_exec_query_stats bqs on cp.plan_handle = bqs.plan_handle CROSS APPLY sys.dm_exec_sql_text(cp.plan_handle) st where cp.objtype = 'proc' and qs.last_execution_time > @LastEx group by DB_NAME(st.dbid) ,OBJECT_SCHEMA_NAME(objectid,st.dbid) ,OBJECT_NAME(objectid,st.dbid) ,bcp.DateStamp order by max(cp.usecounts)-max(bcp.usecounts) desc --Create baseline tables to get a starting count point if object_id(N'tablebackups.dbo._dm_exec_query_stats') is not null drop table tablebackups.dbo._dm_exec_query_stats if object_id(N'tablebackups.dbo._dm_exec_cached_plans') is not null drop table tablebackups.dbo._dm_exec_cached_plans select getdate() as DateStamp,* into tablebackups.dbo._dm_exec_query_stats from sys.dm_exec_query_stats select getdate() as DateStamp,* into tablebackups.dbo._dm_exec_cached_plans from sys.dm_exec_cached_plans
I basically saves the contents of DMVs into tables (tablebackups) so that I can compare the situation as it is now (straight from the DMVs) and the situation as it was (from the tablebackus tables).
Only problem and hence this question:
Sometimes the total_worker_time now is less that what it used to be, for a reason I haven’t identified, and therefore it gives me negative values.
I have been run this script as a stored procedure that is called by a job every 5 min.
so in the last 5 min I know how many times each procedure has been executed, that has been accurate, but the CPU usage has not been, for the reason above.
what can I do to tackle this?
I’m pretty terrible at these DMVs however:
When you’re joining on the history you can have one plan_handle with multiple sql_handle (where the plan executes with different options), so possibly this is skewing your stats.
The plan handle is for an entire batch, with individual statements inside it, which can be recompiled separately, and this might (I haven’t confirmed) overwrite the stats for the batch. You might be able to confirm by capturing with traces/events for plan recompilations and seeing if the times correlate with your counter resets.