Extended Events does not track insert statements by Andrew V Butenko

Hello Andrew,
Thanks for reporting the issue. We have now fixed the problem in the next major version of SQL Server. We have added an optional "parameterized_plan_handle" data field to the "sql_statement_completed" xevent. This will allow you to correlate the data with the actual query plan. Hope this helps.

--
Umachandar, SQL Programmability Team

Hi Andrew,

Jonathan's analysis in the previous post is accurate. The plan_handle action of the sql_statement_completed event returns the handle to the unparameterized insert query, and its plan, were it cached, would point to the parameterized plan. If you have another select query in the same batch, the batch would be cached and you would get something like this from the plan_handle:
<StmtSimple StatementText="
insert into t1 values(1);
" StatementId="2" StatementCompId="2" StatementType="INSERT" RetrievedFromCache="true" ParameterizedPlanHandle="0x06000200C12FFB1FF06DF17E0300000001000000000000000000000000000000000000000000000000000000" ParameterizedText="(@1 int)INSERT INTO [t1] values(@1)" />

We can not make the plan_handle action return the handle to the parameterized plan in this case, as it would not match the data of the event and its other actions, e.g. text and offsets.

I understand that for the task you have in hand, the chain (event session -> plan cache -> query plan) is broken. Unfortunately anything related to plan cache is not guaranteed to stay in memory, even though most of the time it will when there's enough memory. Plan cache is designed to optimize query execution performance, and is free to choose what plans go into and out of cache, and when, based on cost and benefit factors. In this particular case, un-parameterized INSERT VALUES statement, when alone in a batch, is never cached because it's a common cache bloater and almost always has no reuse value.

In the coming SQL Server 2011, sql_statement_completed includes more data and there's a new action query_plan_hash that you can use to find the parameterized query plan using query like "select qp.query_plan from sys.dm_exec_query_stats qs cross apply sys.dm_exec_query_plan(qs.plan_handle) qp where convert(bigint, qs.query_plan_hash) = 7936584214303716748". I'm also considering adding ParameterizedPlanHandle to the event data of sql_statement_completed so that it doesn't depend on the outer query being cached.

However to get these in SQL Server 2008 R2 you'll have to open a hotfix request. I can not think of any workaround right now that would get you through the missing link. You might want to explore other methods of achieving your goal. Even if you can follow the plan_handle, it still depends on the insert plan staying in memory, and will break when system is under memory pressure or plan cache entries are evicted for any reason (e.g. DDL related schema change, or DBCC FREEPROCCACHE). For example, if it's possible to add an insert trigger on the table, you can get the application name from there and it will always be robust.

Thanks,

Haitao Wang

Jonatathan,
I told you in that forum thread and can repeat again. Event Session returns an INCORRECT plan_handle.
It returns usless plan handle:
    <action name="plan_handle" package="sqlserver">
     <type name="unicode_string" package="package0" />
     <value><plan handle='0x06000800F8FC692F40812A87000000000000000000000000'/></value>
     <text />
    </action>
    <action name="sql_text" package="sqlserver">
     <type name="unicode_string" package="package0" />
     <value>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)
</value>
     <text />


It is tipical for insert into tables with cluster index.
As for plan cache bloating - it is only your personal assumption. There is another setting to control cache pollution
sp_configure 'optimize for ad hoc workloads'
and if I switch that option off (=0) that means I want to get ALL queries in my cache. It is absolutely legal for dev/test environment (not production).
Again my point is clear - if event session skip cluster index insert statements plan handles it must be official (non forum moderator!!!) workaround

The Event Session is returning the actual plan_handle at the point of execution for the Event which is an accurate plan_handle at the time the event fired. The problem here is that you are submitting a non-parameterized adhoc insert which doesn't get a cached plan, it gets a cached plan stub for the auto-parameterized execution plan generated by the engine to prevent plan cache bloat from bad coding practices like this. You can validate this by running the following modified version of your repro script which uses a parameterized insert and it will pull the plan from cache using the plan_handle generated by the Event Session as expected:

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)
WHERE sqlserver.database_id=5 --set AdventureWorks2008R2 DB_ID()
)
ADD target package0.ring_buffer
WITH (MAX_DISPATCH_LATENCY=5SECONDS, TRACK_CAUSALITY=ON)
GO

ALTER EVENT SESSION SQLStmtEvents ON SERVER STATE = START;
GO

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 2


-- Shred events out of the target and pull back the plan from cache using the plan_handle action
SELECT event_name,
    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

Hello Andrew,
Thanks for your feedback. We will investigate the issue and get back to you.

--
Umachandar, SQL Programmability Team