Parse and Compile Time: Reading the First Line of STATISTICS TIME

Parse and compile time is the work SQL Server does before it runs your query at all. SET STATISTICS TIME prints it as the first message, and people often misread it. Run the same statement twice and you will see why: the second run usually pays nothing.

Two kinds of time in one Messages tab

Here is a chat I have seen many times. A developer pastes the Messages output and writes, “Compile time is 24 ms. Is the server slow?” They run the query again, and now it says 0 ms. They are even more confused.

Nothing is wrong. Before a query can run, SQL Server has to parse it and build a plan. That is parse and compile time. After that comes execution time, which is the work of reading data. Once a plan is stored in the plan cache, the next call with the same text skips the first part.

So the two numbers answer different questions. High compile time points to a complex query or a plan that keeps being rebuilt. High execution time points to data reading. Mixing them sends you down the wrong path.

Start from a clean cache, the gentle way

For a fair test you want the first call to compile. Do not use DBCC FREEPROCCACHE for that. It empties the plans of the whole server, and every other query pays for it. This command clears the plan cache of the current database only. Run it in a test database.

ALTER DATABASE SCOPED CONFIGURATION CLEAR PROCEDURE_CACHE;

Run the same text twice

The statement below counts system objects per schema. It is stored in a variable so that both calls use exactly the same text, the same parameter type and the same value. Each call prints its own messages.

SET STATISTICS TIME ON;

DECLARE @Stmt nvarchar(max) = N'SELECT s.name AS schema_name, COUNT_BIG(*) AS object_total
FROM sys.objects AS o JOIN sys.schemas AS s ON s.schema_id = o.schema_id
WHERE o.type = @t GROUP BY s.name';

PRINT 'Run 1: first call';
EXEC sys.sp_executesql @Stmt, N'@t char(2)', @t = 'S';
PRINT 'Run 2: same text again';
EXEC sys.sp_executesql @Stmt, N'@t char(2)', @t = 'S';

SET STATISTICS TIME OFF;

Look at the line that says “SQL Server parse and compile time” under each heading. In run 1 it shows real time, in the tens of milliseconds on my machine. In run 2 it shows CPU time 0 and elapsed time 0, because the plan was reused. Your numbers will differ from mine, but the pattern should hold.

A tip on reading the rest. The last “SQL Server Execution Times” entry in each run covers the whole call, compile included. The one above it is the statement itself. Do not add them together, or you count the same work twice.

Make it compile again

Now two ways to force a fresh plan. OPTION (RECOMPILE) asks for a new compile on every call. A tiny change in the text, here one extra space, makes SQL Server treat it as a different statement.

SET STATISTICS TIME ON;

DECLARE @Stmt nvarchar(max) = N'SELECT s.name AS schema_name, COUNT_BIG(*) AS object_total
FROM sys.objects AS o JOIN sys.schemas AS s ON s.schema_id = o.schema_id
WHERE o.type = @t GROUP BY s.name';

DECLARE @WithRecompile nvarchar(max) = @Stmt + N' OPTION (RECOMPILE)';
DECLARE @ExtraSpace nvarchar(max) = REPLACE(@Stmt, N'GROUP BY', N' GROUP BY');

PRINT 'Run 3: OPTION (RECOMPILE)';
EXEC sys.sp_executesql @WithRecompile, N'@t char(2)', @t = 'S';
PRINT 'Run 4: one extra space';
EXEC sys.sp_executesql @ExtraSpace, N'@t char(2)', @t = 'S';

SET STATISTICS TIME OFF;

Both runs show compile time again. In run 3 you get two compile lines, and the second one belongs to the statement. That is why text matters. An app that builds its SQL by gluing strings together can compile far more often than you expect. The plan cache shows the damage: two cached plans, one used twice and one used once. The RECOMPILE run left no cached plan at all.

SELECT CASE WHEN st.text LIKE N'%  GROUP BY%' THEN 'extra space version' ELSE 'original text' END AS statement_version,
       cp.usecounts
FROM sys.dm_exec_cached_plans AS cp
CROSS APPLY sys.dm_exec_sql_text(cp.plan_handle) AS st
WHERE st.text LIKE N'%object_total%' AND st.text NOT LIKE N'%dm_exec_cached_plans%'
ORDER BY statement_version;

What not to conclude

This test is tiny, so numbers can round to zero, and the figures move from run to run. Zero on the screen does not mean no work happened. One first-run message cannot tell you your daily CPU cost. If compile time keeps showing up on a busy server, collect it over many calls before you touch any cache setting.

Next time someone pastes a compile time, ask for the second run too.

Compilation time is not execution time, it is work that prepares the execution choice.

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