CPU-Bound Queries: Comparing worker_time to elapsed_time

CPU-bound queries are the ones where CPU time and elapsed time are close to each other. If a query is slow but barely uses CPU, it is waiting, and more processors will not help. Compare the two numbers first, then decide what to fix.

Slow does not mean busy

A manager says the report is slow, so the server needs more CPU. Maybe. But a slow report may be working hard. Or it may be sitting still, waiting for a lock, a disk, or a client. Those two problems have different fixes.

SQL Server keeps two clocks for every request. Worker time is the processor time used. Elapsed time is the wall-clock time from start to finish. The gap between them tells you which kind of slow you have.

Let me build three small procedures so you can see all three shapes. One burns CPU on a single core. One just waits for two seconds. One burns CPU on several cores at once. The demo creates the procedures and drops them at the end.

DROP PROCEDURE IF EXISTS dbo.BusyReport;
DROP PROCEDURE IF EXISTS dbo.IdleReport;
DROP PROCEDURE IF EXISTS dbo.ParallelReport;
GO
CREATE PROCEDURE dbo.BusyReport AS
SELECT SUM(CONVERT(bigint, a.value) * b.value % 7) AS total
FROM GENERATE_SERIES(1, 2000) AS a
CROSS JOIN GENERATE_SERIES(1, 2000) AS b
OPTION (MAXDOP 1);
GO
CREATE PROCEDURE dbo.IdleReport AS
WAITFOR DELAY '00:00:02';
SELECT 1 AS done;
GO
CREATE PROCEDURE dbo.ParallelReport AS
SELECT SUM(CONVERT(bigint, a.value) * b.value % 7) AS total
FROM GENERATE_SERIES(1, 2000) AS a
CROSS JOIN GENERATE_SERIES(1, 2000) AS b
OPTION (MAXDOP 4, USE HINT('ENABLE_PARALLEL_PLAN_PREFERENCE'));

Watch the two clocks

Run each one with SET STATISTICS TIME on. SSMS prints the CPU time and elapsed time in the Messages tab.

SET STATISTICS TIME ON;
EXEC dbo.BusyReport;
EXEC dbo.IdleReport;
EXEC dbo.ParallelReport;
SET STATISTICS TIME OFF;

Your numbers will differ from mine, but the shapes will not. The busy report shows CPU time almost equal to elapsed time. The idle report shows 0 ms of CPU against about 2,000 ms elapsed. That is a waiting query, and no processor upgrade would touch it.

The parallel report is the odd one. On my run its CPU time was well above its elapsed time. Four workers ran at once, so their CPU adds up to more than the clock moved. A ratio above 1 is normal for a parallel plan. It does not mean the numbers are wrong.

Read the ratio from the plan cache

You will not always catch a query live. After it runs, SQL Server keeps its totals while the plan stays in cache. This query divides worker time by elapsed time for each procedure.

SELECT OBJECT_NAME(object_id) AS procedure_name, execution_count,
       total_worker_time, total_elapsed_time,
       total_worker_time * 1.0 / NULLIF(total_elapsed_time, 0) AS cpu_share
FROM sys.dm_exec_procedure_stats
WHERE database_id = DB_ID()
ORDER BY procedure_name;

The busy report has a cpu_share near 1. The idle report is close to 0. The parallel report is above 1. The times are in microseconds, so 2,000,000 means two seconds. Cached numbers disappear when the plan leaves the cache, so compare similar time windows.

For ad hoc queries, sys.dm_exec_query_stats gives the same totals per statement. It also shows the degree of parallelism. On my run last_dop was 4 for the parallel report and 1 for the other two, which explains the ratio above 1.

SELECT TOP (20) q.query_hash, q.execution_count,
       q.total_worker_time, q.total_elapsed_time,
       q.total_worker_time * 1.0 / NULLIF(q.execution_count, 0) AS AverageCpuUs,
       q.total_elapsed_time * 1.0 / NULLIF(q.execution_count, 0) AS AverageElapsedUs,
       q.last_dop, q.min_dop, q.max_dop
FROM sys.dm_exec_query_stats AS q
CROSS APPLY sys.dm_exec_plan_attributes(q.plan_handle) AS a
WHERE a.attribute = N'dbid' AND CONVERT(int, a.value) = DB_ID()
ORDER BY q.total_worker_time DESC, q.query_hash, q.plan_handle, q.statement_start_offset;

Catch the slow request while it is slow

History tells you what happened. For a problem happening right now, look at the live request. This block uses your own session. In real life, put the session number of the slow request in @SessionId.

DECLARE @SessionId int = @@SPID;

SELECT session_id, status, cpu_time, total_elapsed_time,
       wait_type, wait_time, blocking_session_id, dop
FROM sys.dm_exec_requests
WHERE session_id = @SessionId;

SELECT session_id, exec_context_id, wait_type, wait_duration_ms, blocking_session_id
FROM sys.dm_os_waiting_tasks
WHERE session_id = @SessionId
ORDER BY exec_context_id, wait_type;

A request that is running on the processor has no wait_type. A request that is stuck shows its wait and, if a lock is the cause, the blocking session.

Fix the thing you measured

If the query is CPU-bound, look at rows processed, joins and access paths. If it is waiting, find what it waits for: a blocker, storage, or a slow client. Raising parallelism before you find the expensive work can just make the same problem busier.

DROP PROCEDURE IF EXISTS dbo.BusyReport;
DROP PROCEDURE IF EXISTS dbo.IdleReport;
DROP PROCEDURE IF EXISTS dbo.ParallelReport;

Next time somebody asks for more CPU, check the two clocks first.

A slow query is not a CPU problem, it is a question: working or waiting?

Published by Pinal Dave on SQLAuthority. More of my work at pinaldave.com.