TL;DR – The sys.dm_exec_{query|procedure}_stats.*_worker_time fields do not include compile time. But the values in sys.dm_exec_procedure_stats.*_worker_time DO include compile time for ad hoc SQL within the procedures. Also, as a side note, a lot of indexed views can be a significant performance problem.
I recommend a blog post by Jonathan Kehayias entitled, “Identifying High Compile Time Statements from the Plan Cache“. In that, he’s concentrating on queries that have a high individual compile cost.
However, the object of my search was small queries being compiled and executed in high volume (more on why in Part 2 of this). In my case, I was looking for ad hoc SQL being generated and executed inside of stored procedures – the kind of queries that don’t make their way to the plan cache, often due to the use of OPTION (RECOMPILE) to keep them from spamming the cache.
What I found was that worker time needed to compile these queries is indistinguishable from that needed to execute them. To show this, let’s look at an example in AdventureWorks2014. In this example, I’m going to create and execute two similar procedures. I’m also going to create a number of indexed views.
Why indexed views? I want to increase compile time significantly for this exercise, and a large number of indexed views can do that. From MSDN: “The query optimizer may use indexed views to speed up the query execution. The view does not have to be referenced in the query for the optimizer to consider that view for a substitution.” My thanks to oas_public on stackoverflow.com for that tip.
Anyway, let’s create a stored procedure that will use our indexed view:
CREATE PROCEDURE dbo.j1
AS
BEGIN
DECLARE @stmt NVARCHAR(4000);
SELECT @stmt = N'/* dbo.j1 */
SELECT TOP 1
SUM(UnitPrice * OrderQty * (1.00 - UnitPriceDiscount)) AS Rev,
OrderDate,
ProductID
FROM Sales.SalesOrderDetail AS od
INNER JOIN Sales.SalesOrderHeader AS o
ON od.SalesOrderID = o.SalesOrderID
AND ProductID BETWEEN 700 and 800
AND OrderDate >= CONVERT(datetime,''05/01/2002'',101)
GROUP BY OrderDate, ProductID
ORDER BY Rev DESC;';
EXEC(@stmt);
END; --PROCEDURE
GO
By the way, this evolved from sample code on MSDN. Now here’s a second stored procedure that is ever-so-slightly different:
CREATE PROCEDURE dbo.j1
AS
BEGIN
DECLARE @stmt NVARCHAR(4000);
SELECT @stmt = N'/* dbo.j2 */
SELECT TOP 1
SUM(UnitPrice * OrderQty * (2.00 - UnitPriceDiscount)) AS Rev,
OrderDate,
ProductID
FROM Sales.SalesOrderDetail AS od
INNER JOIN Sales.SalesOrderHeader AS o
ON od.SalesOrderID = o.SalesOrderID
AND ProductID BETWEEN 700 and 800
AND OrderDate >= CONVERT(datetime,''05/01/2002'',101)
GROUP BY OrderDate, ProductID
ORDER BY Rev DESC;';
EXEC(@stmt);
END; --PROCEDURE
GO
To make this a fair test, let’s clear the cache:
DBCC FREEPROCCACHE;
GO
And execute both of the procedures:
EXEC dbo.j1;
EXEC dbo.j2;
How long did they take?
SELECT OBJECT_NAME(object_id) AS 'procedure_name', total_worker_time / 1000 AS 'cpu_in_ms'
FROM sys.dm_exec_procedure_stats
WHERE object_id IN (OBJECT_ID('dbo.j1'), OBJECT_ID('dbo.j2'))
ORDER BY OBJECT_NAME(object_id);
On my local system, both run in about 85-105 ms. Obviously, YMMV.
Now let’s create an indexed view. I’m going to reuse this code a couple of times, so bear that in mind when you see how it’s constructed:
--Set the options to support indexed views.
SET NUMERIC_ROUNDABORT OFF;
SET ANSI_PADDING, ANSI_WARNINGS, CONCAT_NULL_YIELDS_NULL, ARITHABORT, QUOTED_IDENTIFIER, ANSI_NULLS ON;
GO
DECLARE @i INT = 1, @stmt NVARCHAR(4000), @t1 NVARCHAR(4000), @t2 NVARCHAR(4000), @t3 NVARCHAR(4000)
-- Create template for dropping the view.
SELECT @t1 = N'/* jtest */
IF OBJECT_ID(''Sales.vOrders_{1}'') IS NOT NULL
DROP VIEW Sales.vOrders_{1};';
-- Create template for creating the view.
SELECT @t2 = N'/* jtest */
CREATE VIEW Sales.vOrders_{1} WITH SCHEMABINDING
AS
SELECT
SUM(UnitPrice*OrderQty*(1.00-UnitPriceDiscount)) AS Revenue,
OrderDate,
ProductID,
COUNT_BIG(*) AS COUNT
FROM Sales.SalesOrderDetail AS od
INNER JOIN Sales.SalesOrderHeader AS o
ON od.SalesOrderID = o.SalesOrderID
GROUP BY OrderDate, ProductID;';
-- Create template for creating the index.
SELECT @t3 = N'/* jtest */
CREATE UNIQUE CLUSTERED INDEX IDX_V1_{1}
ON Sales.vOrders_{1} (OrderDate, ProductID);';
-- Drop and create the objects.
WHILE (@i <= 1)
BEGIN
SELECT @stmt = REPLACE(@t1, N'{1}', CAST(@i AS NVARCHAR(4000)));
EXEC (@stmt);
SELECT @stmt = REPLACE(@t2, N'{1}', CAST(@i AS NVARCHAR(4000)));
EXEC (@stmt);
SELECT @stmt = REPLACE(@t3, N'{1}', CAST(@i AS NVARCHAR(4000)));
EXEC (@stmt);
SELECT @i = @i + 1;
END; --WHILE
GO
Note that the indexed view supports dbo.j1, but not dbo.j2. Let’s go back and run those again:
DBCC FREEPROCCACHE;
GO
EXEC dbo.j1;
EXEC dbo.j2;
SELECT OBJECT_NAME(object_id) AS 'procedure_name', total_worker_time / 1000 AS 'cpu_in_ms'
FROM sys.dm_exec_procedure_stats
WHERE object_id IN (OBJECT_ID('dbo.j1'), OBJECT_ID('dbo.j2'))
ORDER BY OBJECT_NAME(object_id);
GO
If your results are like mine, you’ll see that dbo.j1 has dropped to about a quarter of its previous worker time, but dbo.j2 hasn’t budged. So, our indexed view is doing what we want. Now let’s create a few more. How does 500 sound? In that WHILE loop for the indexed view script, change the constant from 1 to 500 and run it again. Bear in mind, this took about 90 seconds on my system, so be prepared to wait.
Once all 500 indexed views are created, execute the two stored procedures again and look at the results. Both worker time values will be much higher!
But the actual execution time hasn’t changed. We’re still going to get essentially the same plan for each query, which means SQL Server should be doing the same work to execute it. But now the compilation is much more costly because the optimizer is looking at all 500 views when generating the plan. And because that compilation is taking place inside of ad hoc SQL in a stored procedure, SQL Server is reporting it as part of the procedure’s worker time in sys.dm_exec_procedure_stats.
To verify this, you can run Jonathan’s code, which will break out the compile time for those ad hoc queries.
If you’ve been following along in your own database and want to gracefully clean up the mess, you’ll want to do two things. First, execute this:
DROP PROCEDURE dbo.j1;
DROP PROCEDURE dbo.j2;
GO
And second, go back to the indexed view script, comment or remove the last two EXEC lines, and run it again.
In conclusion, the *_worker_time fields in sys.dm_exec_query_stats and sys.dm_exec_procedure_stats do NOT include compile time. That was why Jonathan had to dig into the cached plan and tease that information out of the XML. But the compile time of ad hoc statements inside of a stored procedure WILL be included in the procedure’s execution time.
And too many indexed views can suck.
Stay tuned for Part 2, which explains why I chased this down in the first place.
