Predicaatvolgorde is belangrijk in uitgebreide evenementen

In elke presentatie die ik geef over Extended Events, probeer ik een van de grootste verschillen tussen filteren in Extended Events en filteren in Trace uit te leggen; het feit dat de predikaatvolgorde van belang is in Extended Events. Meestal heb ik het over het kortsluiten van predikaatevaluatie in Extended Events, en proberen om het eventpredikaat zo snel mogelijk een logische evaluatie te laten mislukken om de controle terug te geven aan de uitvoerende taak. Ik werkte onlangs met een van mijn voorbeeldevenementsessies die ik gebruik in presentaties die een ander belangrijk aspect van predikaatvolgorde in uitgebreide evenementen demonstreert.

Binnen Extended Events zijn er tekstuele predikaatvergelijkers die complexere definities van de filtercriteria voor een gebeurtenis mogelijk maken. Een paar hiervan behouden feitelijk een interne status terwijl de gebeurtenissessie op de server wordt gestart, bijvoorbeeld de comparators package0.greater_than_max_uint64 en package0.less_than_min_uint64. Er is ook een predikaat source-element, package0.counter, dat ook een interne status handhaaft wanneer de gebeurtenissessie wordt gestart. Voor de statusbehoudende predikaten in uitgebreide gebeurtenissen is een van de belangrijkste overwegingen dat de interne status verandert wanneer het statusbehoudende predikaat wordt geëvalueerd, niet wanneer de gebeurtenis volledig wordt geactiveerd. Laten we, om dit te demonstreren, eens kijken naar een voorbeeld van het gebruik van de package0.greater_than_max_uint64 tekstuele predikaatvergelijker. Eerst moeten we een opgeslagen procedure maken waarvan we de uitvoeringsduur kunnen regelen van:

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

Vervolgens moeten we een gebeurtenissessie maken om de uitvoeringen van de opgeslagen procedure te volgen met behulp van de gebeurtenis sqlserver.module_end, en de uitvoeringen filteren op de kolommen object_id en source_database_id die door de gebeurtenis worden geleverd. We zullen ook een filter definiëren met behulp van de tekstcomparator package0.greater_than_max_uint64 tegen de duurkolom, die in microseconden is in Extended Events, met een initiële status van 1000000 of één seconde. Met deze toevoeging aan het predikaat wordt de gebeurtenis alleen geactiveerd wanneer de duur de initiële waarde van 1000000 microseconden overschrijdt, en vervolgens zal het predikaat de nieuwe statuswaarde intern opslaan, zodat de gebeurtenis niet opnieuw volledig wordt geactiveerd totdat de duur de waarde overschrijdt. nieuwe interne toestandswaarde. Zodra we de gebeurtenissessie hebben gemaakt, die in dit geval dynamische SQL gebruikt omdat we geen parametrisering in DDL-instructies in SQL Server kunnen gebruiken, wordt deze op de server gestart en kunnen we onze opgeslagen voorbeeldprocedure uitvoeren en de uitvoeringsduur meerdere keren regelen om te zien hoe de gebeurtenis met ons predikaat werd geactiveerd.

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;

Als je mijn blog op SQLskills.com leest, weet je waarschijnlijk dat ik om een ​​aantal redenen geen grote fan ben van het gebruik van het ring_buffer-doel in Extended Events. Voor deze beperkte gegevensverzameling, en het feit dat de gebeurtenissessie deze beperkt tot maximaal tien gebeurtenissen, is het een gemakkelijk doelwit om het gedrag van de gebeurtenispredikaatvolgorde aan te tonen, maar we moeten de XML voor de gebeurtenissen nog steeds handmatig versnipperen om bekijk de resultaten.

-- 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);

Het uitvoeren van de bovenstaande code resulteert in slechts 2 gebeurtenissen, één voor de ene seconde en de andere voor de uitvoeringen van twee seconden. De andere uitvoeringen van de opgeslagen procedure zijn korter dan het initiële filter van één seconde dat is gespecificeerd in microseconden in het predikaat, en vervolgens is de laatste uitvoering van één seconde korter dan de opgeslagen statuswaarde van twee seconden door de comparator. Dit is het verwachte gedrag van de gebeurtenisverzameling, maar als we de predikaatvolgorde wijzigen zodat het filter package0.greater_than_max_uint64(duration, 1000000) als eerste in de predikaatvolgorde voorkomt, en een tweede opgeslagen procedure maken die we uitvoeren met een duur van drie seconden eerst krijgen we helemaal geen evenementen.

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;

In dit geval wordt, omdat de statushandhavingscomparator het eerst in de predikaatvolgorde voorkomt, de interne waarde verhoogd met de drie seconden durende uitvoering van de tweede opgeslagen procedure, ook al faalt de gebeurtenis later door het object_id-filter van het predikaat en wordt niet volledig geactiveerd. Dit gedrag treedt op bij elk van de statussen die predikaten in Extended Events handhaaft. Ik had dit gedrag eerder ontdekt met de bronkolom van het predikaat package0.counter, maar realiseerde me niet dat het gedrag optreedt voor enig deel van het predikaat dat een status handhaaft. De interne status verandert zodra dat deel van het predikaat wordt geëvalueerd. Om deze reden moet elk predikaatfilter dat de status wijzigt of handhaaft het absoluut laatste deel van de predikaatdefinitie zijn om ervoor te zorgen dat het de status alleen intern wijzigt wanneer alle predikaatvoorwaarden de evaluatie hebben doorstaan.