1

I need to track CPU time (not duration!) used by a stored procedure.

Procedure has many SQL statements inside it.

I've tried module_end event in Extended Events, but it does not have cpu_time field (it has collect_cpu_cycle_time, not sure what's that and in which units of measure).

Also tried sp_WhoIsActive - watching CPU column during procedure's execution, this gives a good idea how much cpu time procedure spends, but obviously not very exact method.

Need some method that would allow to get exact CPU time used by each stored procedure's call, preferably with ability to log it to a table, log file, etc.

1
  • sp_blitzcache also has a parameter to input a stored proc name to get some stats about it, including CPU time Commented Dec 22, 2023 at 12:47

2 Answers 2

2

What about using sys.dm_exec_procedure_stats? This has a total_worker_time column which is your CPU time. You can take snapshots of this DMV and subtract from the previous snapshot to get what has occurred since the last sample.

I created a monitoring tool, DBA Dash that does this if you are interested. It's free & open source.

DBA Dash Object Execution Stats

Depending on how the SP is being called, the RPC completed event might also work for you.

Hope this helps.

1
  • thanks David, I'll check that out in next few days Commented Dec 22, 2023 at 12:30
1

If you have QueryStore enabled you can get this information from there (aggregated but with greater granularity than sys.dm_exec_procedure_stats offers).

An example query to use as a starting point is below.

Currently it groups by plan_id and execution_type_desc but you could change that as desired. sys.query_store_query has an object_id column that can be filtered on if you only care about a specific proc.


/*Actual time range returned may be greater than requested as can't return any more granular than how it is aggregated */
DECLARE @StartTime DATETIME2 = '2023-12-23 00:00:00.000', 
        @EndTime DATETIME2 = '2023-12-23 10:59:00.000',
        @StartRuntimeStatsIntervalId BIGINT,
        @EndRuntimeStatsIntervalId BIGINT;


SELECT TOP 1 @StartRuntimeStatsIntervalId =  runtime_stats_interval_id, @StartTime = start_time
FROM sys.query_store_runtime_stats_interval
WHERE end_time > @StartTime 
ORDER BY runtime_stats_interval_id;

select  TOP 1 @EndRuntimeStatsIntervalId =runtime_stats_interval_id, @EndTime = end_time
from sys.query_store_runtime_stats_interval
WHERE  start_time <= @EndTime
ORDER BY runtime_stats_interval_id DESC;


SELECT Info = CONCAT('Runtime stats intervals range covered is "BETWEEN ',@StartRuntimeStatsIntervalId, ' AND ' ,@EndRuntimeStatsIntervalId,'". Time Range covered is ', @StartTime, ' to ', @EndTime);


with waits As
(
SELECT ws.plan_id, 
       ws.execution_type_desc,
       waits_Unknown = SUM(CASE WHEN wait_category = 0 THEN total_query_wait_time_ms ELSE 0 END),
       waits_CPU = SUM(CASE WHEN wait_category = 1 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Worker_Thread = SUM(CASE WHEN wait_category = 2 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Lock = SUM(CASE WHEN wait_category = 3 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Latch = SUM(CASE WHEN wait_category = 4 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Buffer_Latch = SUM(CASE WHEN wait_category = 5 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Buffer_IO = SUM(CASE WHEN wait_category = 6 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Compilation = SUM(CASE WHEN wait_category = 7 THEN total_query_wait_time_ms ELSE 0 END),
       waits_SQL_CLR = SUM(CASE WHEN wait_category = 8 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Mirroring = SUM(CASE WHEN wait_category = 9 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Transaction = SUM(CASE WHEN wait_category = 10 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Idle = SUM(CASE WHEN wait_category = 11 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Preemptive = SUM(CASE WHEN wait_category = 12 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Service_Broker = SUM(CASE WHEN wait_category = 13 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Tran_Log_IO = SUM(CASE WHEN wait_category = 14 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Network_IO = SUM(CASE WHEN wait_category = 15 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Parallelism = SUM(CASE WHEN wait_category = 16 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Memory = SUM(CASE WHEN wait_category = 17 THEN total_query_wait_time_ms ELSE 0 END),
       waits_User_Wait = SUM(CASE WHEN wait_category = 18 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Tracing = SUM(CASE WHEN wait_category = 19 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Full_Text_Search = SUM(CASE WHEN wait_category = 20 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Other_Disk_IO = SUM(CASE WHEN wait_category = 21 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Replication = SUM(CASE WHEN wait_category = 22 THEN total_query_wait_time_ms ELSE 0 END),
       waits_Log_Rate_Governor = SUM(CASE WHEN wait_category = 23 THEN total_query_wait_time_ms ELSE 0 END),
       waits_total = SUM(total_query_wait_time_ms)
FROM sys.query_store_wait_stats ws
WHERE ws.runtime_Stats_interval_id BETWEEN @StartRuntimeStatsIntervalId AND @EndRuntimeStatsIntervalId
GROUP BY ws.plan_id, ws.execution_type_desc
), runtime_stats AS
(
SELECT rs.plan_id, 
       rs.execution_type_desc, 
       count_executions = SUM(count_executions),
       first_execution_time = MIN(first_execution_time), 
       last_execution_time = MAX(last_execution_time),
       total_duration_ms = SUM(count_executions * avg_duration)/1000,
       total_cpu_time_ms = SUM(count_executions * avg_cpu_time)/1000,
       total_logical_io_reads = SUM(count_executions * avg_logical_io_reads),          
       total_physical_io_reads = SUM(count_executions * avg_physical_io_reads),  
       total_logical_io_writes = SUM(count_executions * avg_logical_io_writes),    
       total_log_bytes_used = SUM(count_executions * avg_log_bytes_used),      
       total_dop = SUM(avg_dop * count_executions),
       max_duration_ms = MAX(max_duration)/1000
FROM sys.query_store_runtime_stats rs
WHERE rs.runtime_Stats_interval_id BETWEEN @StartRuntimeStatsIntervalId AND @EndRuntimeStatsIntervalId
GROUP BY rs.plan_id, rs.execution_type_desc
)
SELECT qt.query_sql_text,
       rs.count_executions,
       rs.first_execution_time,
       rs.last_execution_time,
       rs.total_duration_ms,
       rs.max_duration_ms,
       rs.total_cpu_time_ms,
       rs.total_logical_io_reads,
       rs.total_physical_io_reads,
       rs.total_logical_io_writes,
       rs.total_log_bytes_used,
       avg_dop = rs.total_dop / count_executions,
       object_name = OBJECT_SCHEMA_NAME(q.object_id) + '.' + OBJECT_NAME(q.object_id),
       rs.plan_id,
       rs.execution_type_desc,
       w.waits_Unknown,
       w.waits_CPU,
       w.waits_Worker_Thread,
       w.waits_Lock,
       w.waits_Latch,
       w.waits_Buffer_Latch,
       w.waits_Buffer_IO,
       w.waits_Compilation,
       w.waits_SQL_CLR,
       w.waits_Mirroring,
       w.waits_Transaction,
       w.waits_Idle,
       w.waits_Preemptive,
       w.waits_Service_Broker,
       w.waits_Tran_Log_IO,
       w.waits_Network_IO,
       w.waits_Parallelism,
       w.waits_Memory,
       w.waits_User_Wait,
       w.waits_Tracing,
       w.waits_Full_Text_Search,
       w.waits_Other_Disk_IO,
       w.waits_Replication,
       w.waits_Log_Rate_Governor,
       w.waits_total
FROM   runtime_stats rs 
       JOIN sys.query_store_plan p
         ON rs.plan_id = p.plan_id
       JOIN sys.query_store_query q
         ON p.query_id = q.query_id
       JOIN sys.query_store_query_text qt
         ON q.query_text_id = qt.query_text_id
       LEFT JOIN waits w
         ON w.plan_id = rs.plan_id
            AND w.execution_type_desc = rs.execution_type_desc
ORDER  BY total_duration_ms DESC

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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