Sql-server – How to read “CPU (ms/sec)” in the “Recent Expensive Queries” of Activity Monitor

sql serversql-server-2008

Is CPU (ms/sec) the cpu time in ms in previous second? If it reaches 1000, does it means that it uses 100% CPU?

However, on my 8 cores server, the % Processor Time is usually very low like several percent when the most expensive query in the "Recent Expensive Queries" reaches 1000.

Best Answer

This is the ratio of CPU time used by that query per second. Internally to SQL Server in this DMV (sys.dm_exec_query_stats) CPU time is measured in microseconds and the report is pulling the usage per second. However, the ms in the report is in milliseconds for the Activity Monitor and microsecond would be mcs.

The reason you're seeing 1000 in this result set could be because that query used all CPU time for that one-second interval. Restated, it has used 1000 ms of CPU time for that second. On a system with multiple schedulers (sys.dm_os_schedulers), it is possible to have queries go parallel and use multiple schedulers and have > 1000ms/sec of CPU time. In your example below, 500ms of CPU time for the SQLOS scheduler has been consumed by that query in the last second. This means that 50% of one CPU's time was dedicated to this query. Note that it could have been a parallel query and only used 10% of five schedulers (which correlate to the number of CPUs). Depending on the timing of these parallel threads, it could present as low CPU usage in the % Processor Time. In your performance monitor are you looking at the _Total or per processor? Also, you can run the query below to see how SQL Server is reporting its own CPU utilization (thank you Glenn Berry).

DECLARE @ts_now BIGINT;
SELECT @ts_now = cpu_ticks/(cpu_ticks/ms_ticks)FROM sys.dm_os_sys_info;         
SELECT TOP(10) 
    SQLProcessUtilization AS sql_server_process_cpu,
    SystemIdle AS system_idle_process_cpu,
    100 - SystemIdle - SQLProcessUtilization AS other_process_cpu,
    DATEADD(ms, -1 * (@ts_now - [timestamp]), GETDATE()) AS event_time
    FROM (
            SELECT 
                record.value('(./Record/@id)[1]', 'int') AS record_id,
                record.value('(./Record/SchedulerMonitorEvent/SystemHealth/SystemIdle)[1]', 'int') AS [SystemIdle],
                record.value('(./Record/SchedulerMonitorEvent/SystemHealth/ProcessUtilization)[1]','int') AS [SQLProcessUtilization], 
                [timestamp]
            FROM (
                    SELECT [timestamp], convert(xml, record) AS [record]
                    FROM sys.dm_os_ring_buffers
                    WHERE ring_buffer_type = N'RING_BUFFER_SCHEDULER_MONITOR'
                        AND record LIKE '%<SystemHealth>%') AS x
                  ) AS y
    ORDER BY record_id DESC;

Do keep in mind that total_worker_time is the amount of CPU time used by the query since the plan was compiled*. Take a look at the Executions/min right next to the CPU (ms/sec) in the report to get a sense of whether or not this query plan has been used multiple times. Note: This may require math. Having said all of this, I fired up Activity Monitor and looked at one of the queries that was showing high CPU time on a development instance. I then went to the DMV to look at total_cpu_time for that query and the number is quite high (which is to be expected). This leads me to believe that the math is being handled internally by Activity Monitor and is taking the difference between current total_cpu_time and what it knew the total_cpu_time to be 1 second ago.

So in summary, this is showing you how much total_cpu_time in microseconds the query in question has used in the last second.

I'd also make a note of that query and look at the sys.dm_exec_query_stats results for that query plan hash and look at the other information provided by that DMV.

Related Question