Predikatordning spelar roll i utökade evenemang

I varje presentation jag ger om Extended Events försöker jag förklara en av de största skillnaderna mellan filtrering i Extended Events och filtrering i Trace; det faktum att predikatordning spelar roll i Extended Events. För det mesta pratar jag om kortslutning av predikatutvärdering i Extended Events, och att försöka få händelsepredikatet att misslyckas logisk utvärdering så snabbt som möjligt för att återställa kontrollen till den exekverande uppgiften. Jag arbetade nyligen med en av mina exempelhändelssessioner som jag använder i presentationer som visar en annan viktig aspekt av predikatordning i utökade evenemang.

Inom Extended Events finns det textuella predikatjämförare som möjliggör mer komplexa definitioner av filtreringskriterierna för en händelse. Några av dessa upprätthåller faktiskt ett internt tillstånd medan händelsesessionen startas på servern, till exempel komparatorerna package0.greater_than_max_uint64 och package0.less_than_min_uint64. Det finns också ett predikatkällelement, package0.counter, som också upprätthåller ett internt tillstånd när händelsesessionen startas. För tillståndsupprätthållande predikat i utökade händelser är en av de viktigaste övervägandena att det interna tillståndet ändras närhelst det tillståndsupprätthållande predikatet utvärderas, inte när händelsen utlöses helt. För att demonstrera detta, låt oss ta en titt på ett exempel på användningen av package0.greater_than_max_uint64 textuella predikatkomparator. Först måste vi skapa en lagrad procedur som vi kan kontrollera exekveringstiden för:

USE AdventureWorks2012
GO
IF OBJECT_ID(N'StoredProcedureExceedsDuration') IS NOT NULL
       DROP PROCEDURE dbo.StoredProcedureExceedsDuration;
GO
CREATE PROCEDURE dbo.StoredProcedureExceedsDuration
( @WaitForValue varchar(12) = '00:00:00:050')
AS
       WAITFOR DELAY @WaitForValue;      
GO

Sedan kommer vi att behöva skapa en händelsesession för att spåra körningarna av den lagrade proceduren med hjälp av händelsen sqlserver.module_end, och filtrerar körningarna på kolumnerna object_id och source_database_id som tillhandahålls av händelsen. Vi kommer också att definiera ett filter som använder textkomparatorn package0.greater_than_max_uint64 mot varaktighetskolumnen, som är i mikrosekunder i Extended Events, med ett initialt tillstånd på 1000000 eller en sekund. Med detta tillägg till predikatet kommer händelsen bara att aktiveras när varaktigheten överstiger det initiala värdet på 1000000 mikrosekunder, och sedan kommer predikatet att lagra det nya tillståndsvärdet internt, så att händelsen inte aktiveras helt igen förrän varaktigheten överskrider nytt internt tillståndsvärde. När vi väl har skapat händelsesessionen, som i det här fallet använder Dynamic SQL eftersom vi inte kan använda parametrisering i DDL-satser i SQL Server, kommer den att startas på servern och vi kan köra vårt exempel på lagrad procedur och kontrollera exekveringslängden flera gånger för att titta på hur händelsen avfyrades med vårt predikat.

IF EXISTS(SELECT * 
         FROM sys.server_event_sessions 
         WHERE name='StatementExceedsLastDuration') 
    DROP EVENT SESSION [StatementExceedsLastDuration] ON SERVER; 
GO
-- Build the event session using dynamic SQL to concatenate the database_id 
-- and object_id in the DDL, parameterization is not allowed in DDL!
DECLARE @ObjectID    NVARCHAR(10)  = OBJECT_ID('StoredProcedureExceedsDuration'),
              @DatabaseID NVARCHAR(10)   = DB_ID('AdventureWorks2012');
DECLARE @SqlCmd            NVARCHAR(MAX) ='
CREATE EVENT SESSION [StatementExceedsLastDuration] ON SERVER
ADD EVENT sqlserver.module_end(
       SET collect_statement = 1
       WHERE  (object_id = ' + @ObjectID + ' AND 
                      source_database_id = ' + @DatabaseID + ' AND
                     package0.greater_than_max_uint64(duration, 1000000)))
ADD TARGET package0.ring_buffer(SET max_events_limit=10);'
 
EXECUTE(@SqlCmd)
 
ALTER EVENT SESSION [StatementExceedsLastDuration]
ON SERVER
STATE=START;
 
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:01.000';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:02.000';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:01.000';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;

Om du läser min blogg på SQLskills.com vet du förmodligen att jag inte är ett stort fan av att använda ring_buffer-målet i Extended Events av flera anledningar. För denna begränsade datainsamling, och det faktum att händelsesessionen begränsar den till högst tio händelser, är det ett enkelt mål att demonstrera beteendet hos händelsepredikatordningen, men vi behöver fortfarande fragmentera XML för händelserna manuellt för att se resultatet.

-- Shred events out of the target
SELECT
    event_data.value('(@name)[1]', 'nvarchar(50)') AS event_name,
    event_data.value('(@timestamp)[1]', 'datetime2') AS [timestamp],
    event_data.value('(data[@name="duration"]/value)[1]', 'bigint') as duration,
    event_data.value('(data[@name="statement"]/value)[1]', 'varchar(max)') as [statement]
FROM (  SELECT CAST(target_data AS xml) AS TargetData
        FROM sys.dm_xe_sessions AS s
        INNER JOIN sys.dm_xe_session_targets AS t
            ON s.address = t.event_session_address
        WHERE s.name = N'StatementExceedsLastDuration'
          AND t.target_name = N'ring_buffer' ) AS tab
CROSS APPLY TargetData.nodes (N'RingBufferTarget/event') AS evts(event_data);

Att köra koden ovan kommer att resultera i bara 2 händelser, en för en sekund och sedan den andra för de två sekunderna körningarna. De andra exekveringarna av den lagrade proceduren är kortare än det initiala ensekundsvaraktighetsfiltret specificerat i mikrosekunder i predikatet, och sedan är den sista ensekundsexekveringen kortare i varaktighet än det lagrade tillståndsvärdet på två sekunder av komparatorn. Detta är det förväntade beteendet för händelsesamlingen, men om vi ändrar predikatordningen så att filtret package0.greater_than_max_uint64(duration, 1000000) inträffar först i predikatordningen och skapar en andra lagrad procedur som vi kör med en varaktighet på tre sekunder först kommer vi inte att få några händelser alls.

USE AdventureWorks2012
GO
IF OBJECT_ID(N'StoredProcedureExceedsDuration') IS NOT NULL
       DROP PROCEDURE dbo.StoredProcedureExceedsDuration;
GO
CREATE PROCEDURE dbo.StoredProcedureExceedsDuration
( @WaitForValue varchar(12) = '00:00:00:050')
AS
       WAITFOR DELAY @WaitForValue;      
GO
IF OBJECT_ID(N'StoredProcedureExceedsDuration2') IS NOT NULL
       DROP PROCEDURE dbo.StoredProcedureExceedsDuration2;
GO
CREATE PROCEDURE dbo.StoredProcedureExceedsDuration2
( @WaitForValue varchar(12) = '00:00:00:050')
AS
       WAITFOR DELAY @WaitForValue;      
GO
IF EXISTS(SELECT * 
         FROM sys.server_event_sessions 
         WHERE name='StatementExceedsLastDuration') 
    DROP EVENT SESSION [StatementExceedsLastDuration] ON SERVER; 
GO
-- Build the event session using dynamic SQL to concatenate the database_id 
-- and object_id in the DDL, parameterization is not allowed in DDL!
DECLARE @ObjectID    NVARCHAR(10)  = OBJECT_ID('StoredProcedureExceedsDuration'),
              @DatabaseID NVARCHAR(10)   = DB_ID('AdventureWorks2012');
DECLARE @SqlCmd            NVARCHAR(MAX) ='
CREATE EVENT SESSION [StatementExceedsLastDuration] ON SERVER
ADD EVENT sqlserver.module_end(
       SET collect_statement = 1
       WHERE  (package0.greater_than_max_uint64(duration, 1000000) AND
                     object_id = ' + @ObjectID + ' AND 
                      source_database_id = ' + @DatabaseID + '))
ADD TARGET package0.ring_buffer(SET max_events_limit=10);'
 
EXECUTE(@SqlCmd)
 
ALTER EVENT SESSION [StatementExceedsLastDuration]
ON SERVER
STATE=START;
 
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration2 '00:00:03.050';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:01.050';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:02.050';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;

I det här fallet, eftersom tillståndsupprätthållande komparatorn inträffar först i predikatordningen, ökas dess interna värde med tre sekunders exekvering av den andra lagrade proceduren även om händelsen senare misslyckas med objekt_id-filtret för predikatet och inte avfyras helt. Detta beteende inträffar när var och en av staten upprätthåller predikat i utökade händelser. Jag hade tidigare upptäckt detta beteende med källkolumnen package0.counter predikat, men insåg inte att beteendet inträffar för någon del av predikatet som upprätthåller ett tillstånd. Det interna tillståndet kommer att ändras så snart den delen av predikatet utvärderas. Av denna anledning bör alla predikatfilter som ändrar eller upprätthåller tillstånd vara den absolut sista delen av predikatdefinitionen för att säkerställa att det endast modifierar tillståndet internt när alla predikatvillkor har klarat utvärderingen.