The topic for today's post comes from a forums question and a subsequent Connect feedback item where someone noted that the plan_handle being returned by Extended Events using the sqlserver.plan_handle action was not available in the plan cache even when queried immediately following completion of the event that should have produced the plan cache entry.  To setup the appropriate context of this post, let's first take a look at the original repro for this problem.

-- Create the Event Session

IF EXISTS(SELECT * 

          FROM sys.server_event_sessions 

          WHERE name='SQLStmtEvents')

    DROP EVENT SESSION SQLStmtEvents 

    ON SERVER;

GO

CREATE EVENT SESSION SQLStmtEvents

ON SERVER

ADD EVENT sqlserver.sql_statement_completed(

    ACTION (sqlserver.client_app_name,

            sqlserver.plan_handle,

            sqlserver.sql_text,

            sqlserver.tsql_stack,

            package0.callstack,

            sqlserver.request_id)

--Change this to match the AdventureWorks, 

--AdventureWorks2008 or AdventureWorks2008 DB_ID()

WHERE sqlserver.database_id=5 

)

ADD TARGET package0.ring_buffer

WITH (MAX_DISPATCH_LATENCY=5SECONDS, TRACK_CAUSALITY=ON)

GO

-- Start the Event Session

ALTER EVENT SESSION SQLStmtEvents 

ON SERVER 

STATE = START;

GO

-- Change database contexts and insert one row

USE AdventureWorks2008;

GO

INSERT INTO [dbo].[ErrorLog]([ErrorTime],[UserName],[ErrorNumber],[ErrorSeverity],[ErrorState],[ErrorProcedure],[ErrorLine],[ErrorMessage])

VALUES(getdate(),SYSTEM_USER,-1,-1,-1,'ErrorProcedure',-1,'An error occurred')

GO

-- Retrieve the Event Data from the Event Session Target

SELECT

    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,

    CAST(event_data.value('(event/action[@name="plan_handle"]/value)[1]', 'varchar(max)') AS XML) as plan_handle,

    event_data.value('(event/action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text

FROM(    SELECT evnt.query('.') AS event_data

        FROM

        (    SELECT CAST(target_data AS xml) AS TargetData

            FROM sys.dm_xe_sessions AS s

            JOIN sys.dm_xe_session_targets AS t

                ON s.address = t.event_session_address

            WHERE s.name = 'SQLStmtEvents'

              AND t.target_name = 'ring_buffer'

        ) AS tab

        CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS split(evnt) 

     ) AS evts(event_data)

-- Use the plan_handle from one of the Events to get the query plan

DECLARE @plan_handle varbinary(64) = 0x06000800DD8D6D0840015585000000000000000000000000

SELECT * 

FROM sys.dm_exec_query_plan(@plan_handle)

It doesn't matter how many times you run the INSERT statement in the above repro, you won't get a plan_handle back from the Event Session that you can query from the plan cache using sys.dm_exec_query_plan().  However, if you were to search the plan cache XML by parsing it, you would find a cached execution plan for the INSERT statement:

SELECT cp.plan_handle, st.text

FROM sys.dm_exec_cached_plans cp 

CROSS APPLY sys.dm_exec_sql_text(cp.plan_handle) st

WHERE st.text like '%INSERT%INTO%ErrorLog%'

-- Prevent caching this statement

OPTION(RECOMPILE);

The output of this will be similar to:

If you look at the text output you will notice that this isn't exactly the statement that was executed, so what happened here exactly?  When an adhoc statement is submitted to SQL Server, the optimizer will auto parameterize the inline literals with variables to compile the query plan for execution, and this is what is cached in by SQL Server in the case of this INSERT statement.  You can always tell that a plan was auto parameterized by the way that the variables are listed inside of the statement text for the plan.  The topic of plan caching and auto parameterization are covered in detail in the MSDN whitepaper Batch Compilation, Recompilation, and Plan Caching Issues in SQL Server 2005.

The problem in this case is not that Extended Events is returning incorrect information for the plan_handle; the handle that is being returned is valid at the point that the event fired for the adhoc request against SQL Server, the adhoc plan is not cached by the Database Engine, and instead the auto parameterized plan is what is actually cached.  The caching of the auto parameterized plan is actually an optimization inside of SQL Server in this case since the plan for the inline literals is not likely to be reused by the optimizer for subsequent adhoc SQL Statements performing the exact same INSERT operation but with different literals for the values being inserted.  This was discussed at some depth on the SQL Programmability & API Development Team Blog post: 4.0 Query Parameterization.  Under SQL Server 2005 RTM and SQL Server 2005 SP1, there was a significant problem with plan cache bloat related to single use adhoc query plans and a significant change was made to the caching behavior of SQL Server 2005 in SP2 that have been carried forward in the product as detailed in the SQL Programmability & API Development Team Blog post: 3.0 Changes in Caching Behavior between SQL Server 2000, SQL Server 2005 RTM and SQL Server 2005 SP2.

If we change the original repro for this problem to use a parameterized query the plan_handle returned by the sqlserver.plan_handle action will return the same plan_handle that is cached by SQL Server as show in the following modification of the original repro for this problem:

-- Create the Event Session

IF EXISTS(SELECT * 

          FROM sys.server_event_sessions 

          WHERE name='SQLStmtEvents')

    DROP EVENT SESSION SQLStmtEvents 

    ON SERVER;

GO

CREATE EVENT SESSION SQLStmtEvents

ON SERVER

ADD EVENT sqlserver.sql_statement_completed(

    ACTION (sqlserver.client_app_name,

            sqlserver.plan_handle,

            sqlserver.sql_text,

            sqlserver.tsql_stack,

            package0.callstack,

            sqlserver.request_id)

--Change this to match the AdventureWorks, 

--AdventureWorks2008 or AdventureWorks2008 DB_ID()

WHERE sqlserver.database_id=5 

)

ADD TARGET package0.ring_buffer

WITH (MAX_DISPATCH_LATENCY=5SECONDS, TRACK_CAUSALITY=ON)

GO

-- Start the Event Session

ALTER EVENT SESSION SQLStmtEvents 

ON SERVER 

STATE = START;

GO

-- Change database contexts and insert one row parameterized

USE AdventureWorks2008R2;

GO

DECLARE @ErrorTime datetime = GETDATE(),

        @UserName sysname = SYSTEM_USER,

        @ErrorNumber int = -1,

        @ErrorSeverity int = -1,

        @ErrorState int = -1,

        @ErrorProcedure nvarchar(126) = 'ErrorProcedure',

        @ErrorLine int = 10, 

        @ErrorMessage nvarchar(4000) = 'An error occured'

INSERT INTO [dbo].[ErrorLog]

    ([ErrorTime],[UserName],[ErrorNumber],[ErrorSeverity],[ErrorState],

     [ErrorProcedure],[ErrorLine],[ErrorMessage])

VALUES(@ErrorTime,@UserName,@ErrorNumber,@ErrorSeverity,@ErrorState,

        @ErrorProcedure,@ErrorLine,@ErrorMessage)

GO 5

-- Retrieve the Event Data from the Event Session Target

SELECT event_name,

    plan_handle,

    sql_text,

    query_plan

FROM

(

SELECT

    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,

    CAST(event_data.value('(event/action[@name="plan_handle"]/value)[1]', 'varchar(max)') AS XML) as plan_handle,

    event_data.value('(event/action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text

FROM(    SELECT evnt.query('.') AS event_data

        FROM

        (    SELECT CAST(target_data AS xml) AS TargetData

            FROM sys.dm_xe_sessions AS s

            JOIN sys.dm_xe_session_targets AS t

                ON s.address = t.event_session_address

            WHERE s.name = 'SQLStmtEvents'

              AND t.target_name = 'ring_buffer'

        ) AS tab

        CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS split(evnt) 

     ) AS evts(event_data)

) AS tab

CROSS APPLY sys.dm_exec_query_plan(plan_handle.value('xs:hexBinary(substring((plan/@handle)[1], 3))', 'varbinary(max)')) as qp

The output of this execution will result in something similar to the following:

Note that the plan_handle is the same for every execution of the INSERT operation, and the plan is readily available from the plan cache because the statement executed was parameterized explicitly in this case by the declaration of variables.  This is yet another case for why explicit parameterization of queries is so incredibly important in SQL Server and why adhoc statements, despite the coding simplicity for application developers is a bad design pattern.

One item that you might notice that is different about the parameterized version of the repro for this is that I used the GO 5 operation to execute the parameterized version of the INSERT operation multiple times.  The reason behind this is that when I ran the initial test of the parameterized version of the INSERT tonight, the first plan was not cached by the Database Engine.  You might ask why this was the case, and there is a really good reason.  As a part of the SQLskills Immersion Training I take part in as an instructor, I had the 'optimize for adhoc workloads' sp_configure option set on my laptop, and this causes a plan stub to be generated for adhoc batches, which the above parameterize query actually is, for the first execution, and then the full plan is cached on the second execution only.  To mitigate against the second repro being a problem for someone I decided to have it execute the INSERT five consecutive times to force caching of the plan to show that parameterization does impact the actual plan handle returned by sqlserver.plan_handle action.