Get SQL Command Compile time

1. SET STATISTICS TIME ON
It not only tell you the compile time of sql command, but also show you the execution times. when you enable it, all the sql command in the current session will be impacted, so it is a good tool to troubleshooting  only 1 sql command at a time, and it can not get compile time of sql command in other sessions.

USE [AdventureWorks]
GO
set statistics time on
go
exec [uspGetManagerEmployees] 100
go
set statistics time off
go

it will show the compile time as below:

SQL Server parse and compile time: 
   CPU time = 31 ms, elapsed time = 62 ms.

if you run the command again, you will get

SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

that's because execution plan has been in the cache, so no compile needed this time.

2. SQL Profiler (or SQL Trace)
SQL Profiler(Trace) can monitor and get sql command compile time in any client session. it has performance impact, especially using SQL Profiler instead of sp_trace_xxxx.

a) SQL Batch
The Batch compile time =  (SQL:StmtStarting StartTime of the first SQL Statement in the batch) - (SQL:BatchStarting StartTime)

you can enable the sql profiler event as below

 

in the sample below, the sql batch compile time = 49.313 - 48.880 = 433ms

b)Store Procedure
The Store Procedure compile time= (SP:StmtStart StartTime of first SQL Statement in the SP) - (SQL:StmtStarting StartTime of the caller SQL Statement)

select the sqp profiler event as below:

run the sample script below:

USE [AdventureWorks]
GO

DECLARE @return_value int

EXEC @return_value = [dbo].[uspGetEmployeeManagers]
@BusinessEntityID = 100

SELECT 'Return Value' = @return_value

GO

and profiler will capture the event log as below:

so the store procedure compile time = 9.910 - 9.617 = 293 ms

c) Dynamic T-SQL
The compile time of Dynamic Query = ( StartTime of StmtStarting of Dynamic Query ) - (EXEC command StartTime of StmtStarting event in batch or SP)

Here we create a dynamic query within a sql batch, and we select the profile event as below:

run the batch:
Declare @query varchar(max)

set @query='

WITH [EMP_cte]([BusinessEntityID], [OrganizationNode], [FirstName], [LastName], [RecursionLevel]) -- CTE name and columns
AS (
    SELECT e.[BusinessEntityID], e.[OrganizationNode], p.[FirstName], p.[LastName], 0 -- Get the initial list of Employees for Manager n
    FROM [HumanResources].[Employee] e 
INNER JOIN [Person].[Person] p 
ON p.[BusinessEntityID] = e.[BusinessEntityID]
    WHERE e.[BusinessEntityID] = 100
    UNION ALL
    SELECT e.[BusinessEntityID], e.[OrganizationNode], p.[FirstName], p.[LastName], [RecursionLevel] + 1 -- Join recursive member to anchor
    FROM [HumanResources].[Employee] e 
        INNER JOIN [EMP_cte]
        ON e.[OrganizationNode].GetAncestor(1) = [EMP_cte].[OrganizationNode]
INNER JOIN [Person].[Person] p 
ON p.[BusinessEntityID] = e.[BusinessEntityID]
    )

SELECT [EMP_cte].[RecursionLevel], [EMP_cte].[OrganizationNode].ToString() as [OrganizationNode], p.[FirstName] AS ''ManagerFirstName'', p.[LastName] AS ''ManagerLastName'',
    [EMP_cte].[BusinessEntityID], [EMP_cte].[FirstName], [EMP_cte].[LastName] -- Outer select from the CTE
FROM [EMP_cte] 
    INNER JOIN [HumanResources].[Employee] e 
    ON [EMP_cte].[OrganizationNode].GetAncestor(1) = e.[OrganizationNode]
INNER JOIN [Person].[Person] p 
ON p.[BusinessEntityID] = e.[BusinessEntityID]
ORDER BY [RecursionLevel], [EMP_cte].[OrganizationNode].ToString()
OPTION (MAXRECURSION 25) 
'

EXEC (@query)
go


and got the trace log as below

so the dynamic query compile time = 40.677 - 40.350 =  327 ms.

3) DMV
MVP Jonathan has a query on his blog, which can show the compile time of cached execution plan
http://www.sqlskills.com/blogs/jonathan/identifying-high-compile-time-statements-from-the-plan-cache/
but it has limitation as all DMV does, if the plan is not in the cached, you will lose the compile info, and the query is only supported by sql 2008 and higher version.

-- Find high compile resource plans in the plan cache
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
WITH XMLNAMESPACES 
(DEFAULT 'http://schemas.microsoft.com/sqlserver/2004/07/showplan')
SELECT TOP 10
CompileTime_ms,
CompileCPU_ms,
CompileMemory_KB,
qs.execution_count,
qs.total_elapsed_time/1000 AS duration_ms,
qs.total_worker_time/1000 as cputime_ms,
(qs.total_elapsed_time/qs.execution_count)/1000 AS avg_duration_ms,
(qs.total_worker_time/qs.execution_count)/1000 AS avg_cputime_ms,
qs.max_elapsed_time/1000 AS max_duration_ms,
qs.max_worker_time/1000 AS max_cputime_ms,
SUBSTRING(st.text, (qs.statement_start_offset / 2) + 1,
(CASE qs.statement_end_offset
WHEN -1 THEN DATALENGTH(st.text)
ELSE qs.statement_end_offset
END - qs.statement_start_offset) / 2 + 1) AS StmtText,
query_hash,
query_plan_hash
FROM
(
SELECT 
c.value('xs:hexBinary(substring((@QueryHash)[1],3))', 'varbinary(max)') AS QueryHash,
c.value('xs:hexBinary(substring((@QueryPlanHash)[1],3))', 'varbinary(max)') AS QueryPlanHash,
c.value('(QueryPlan/@CompileTime)[1]', 'int') AS CompileTime_ms,
c.value('(QueryPlan/@CompileCPU)[1]', 'int') AS CompileCPU_ms,
c.value('(QueryPlan/@CompileMemory)[1]', 'int') AS CompileMemory_KB,
qp.query_plan
FROM sys.dm_exec_cached_plans AS cp
CROSS APPLY sys.dm_exec_query_plan(cp.plan_handle) AS qp
CROSS APPLY qp.query_plan.nodes('ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple') AS n(c)
) AS tab
JOIN sys.dm_exec_query_stats AS qs
ON tab.QueryHash = qs.query_hash
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) AS st
ORDER BY CompileTime_ms DESC
OPTION(RECOMPILE, MAXDOP 1);

here is the result when I run the query, you can see the same duration 327ms as we got with profiler trace

4. Extended Event
I only test extended event on sql 2012.

a) Use the same way as Profiler trace, you can capture the event as below

b) Capture Query_post_compilation_showplan event
the duration field of Query_post_compilation_showplan show the compile time of the execution plan.
Be careful, it is huge performance impact.

here is an example:

this is a extended event trace for sql dynamic query. you can get the compile by
1. Query_post_compilation_showplan event
the duration is 428 ms (the value of duration is microsecond)

2. the ( StartTime of first StmtStarting of Dynamic Query ) - (EXEC command StartTime) =57.419-56.989=430.

a little difference with value from Query_post_compilation_showplan, but almost the same.