L'ordine dei predicati conta negli eventi estesi

In ogni presentazione che faccio su Eventi estesi, cerco di spiegare una delle maggiori differenze tra il filtraggio in Eventi estesi e il filtraggio in Trace; il fatto che l'ordine dei predicati sia importante negli eventi estesi. La maggior parte delle volte parlo di cortocircuito della valutazione del predicato negli eventi estesi e del tentativo di far fallire la valutazione logica del predicato dell'evento il più rapidamente possibile per restituire il controllo all'attività in esecuzione. Di recente stavo lavorando con una delle mie sessioni di eventi di esempio che utilizzo nelle presentazioni che dimostra un altro aspetto importante dell'ordine dei predicati negli eventi estesi.

All'interno degli eventi estesi sono presenti comparatori di predicati testuali che consentono definizioni più complesse dei criteri di filtraggio per un evento. Alcuni di questi in realtà mantengono uno stato interno mentre la sessione dell'evento viene avviata sul server, ad esempio i comparatori package0.greater_than_max_uint64 e package0.less_than_min_uint64. C'è anche un elemento di origine del predicato, package0.counter, che mantiene anche uno stato interno quando viene avviata la sessione dell'evento. Per i predicati di mantenimento dello stato negli eventi estesi, una delle considerazioni più importanti è che lo stato interno cambia ogni volta che viene valutato il predicato di mantenimento dello stato, non quando l'evento si attiva completamente. Per dimostrarlo, diamo un'occhiata a un esempio di utilizzo del comparatore di predicati testuali package0.greater_than_max_uint64. Per prima cosa dovremo creare una stored procedure che possiamo controllare la durata dell'esecuzione di:

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

Quindi dovremo creare una sessione di eventi per tenere traccia delle esecuzioni della procedura memorizzata utilizzando l'evento sqlserver.module_end e filtrare le esecuzioni sulle colonne object_id e source_database_id fornite dall'evento. Definiremo anche un filtro utilizzando il comparatore testuale package0.greater_than_max_uint64 rispetto alla colonna della durata, che è in microsecondi in Eventi estesi, con uno stato iniziale di 1000000 o un secondo. Con questa aggiunta al predicato, l'evento verrà attivato solo quando la durata supera il valore iniziale di 1000000 microsecondi, quindi il predicato memorizzerà il nuovo valore di stato internamente, in modo che l'evento non si attivi nuovamente finché la durata non supera il nuovo valore di stato interno. Una volta creata la sessione dell'evento, che in questo caso utilizza Dynamic SQL poiché non possiamo utilizzare la parametrizzazione nelle istruzioni DDL in SQL Server, verrà avviata sul server e possiamo eseguire la nostra stored procedure di esempio e controllare la durata dell'esecuzione più volte per vedere come si è attivato l'evento con il nostro predicato.

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;

Se leggi il mio blog su SQLskills.com, probabilmente saprai che non sono un grande fan dell'utilizzo del target ring_buffer negli eventi estesi per una serie di motivi. Per questa raccolta di dati limitata e per il fatto che la sessione dell'evento la limita a un massimo di dieci eventi, è un obiettivo facile dimostrare il comportamento dell'ordine del predicato dell'evento, ma è comunque necessario distruggere l'XML per consentire agli eventi di guarda i risultati.

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

L'esecuzione del codice sopra comporterà solo 2 eventi, uno per un secondo e quindi l'altro per le esecuzioni di due secondi. Le altre esecuzioni della procedura memorizzata sono più brevi del filtro di durata iniziale di un secondo specificato in microsecondi nel predicato, quindi l'esecuzione dell'ultimo secondo ha una durata inferiore rispetto al valore dello stato memorizzato di due secondi dal comparatore. Questo è il comportamento previsto della raccolta di eventi, ma se modifichiamo l'ordine del predicato in modo che il filtro package0.greater_than_max_uint64(duration, 1000000) si verifichi per primo nell'ordine del predicato e creiamo una seconda stored procedure che eseguiamo con una durata di tre prima i secondi, non avremo alcun evento.

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 questo caso, poiché il comparatore di mantenimento dello stato si verifica per primo nell'ordine del predicato, il suo valore interno viene incrementato dei tre secondi di esecuzione della seconda procedura memorizzata anche se l'evento in seguito non supera il filtro object_id del predicato e non si attiva completamente. Questo comportamento si verifica con ogni stato che mantiene i predicati negli eventi estesi. In precedenza avevo scoperto questo comportamento con la colonna dell'origine del predicato package0.counter, ma non mi ero reso conto che il comportamento si verifica per nessuna parte del predicato che mantiene uno stato. Lo stato interno cambierà non appena quella parte del predicato sarà valutata. Per questo motivo, qualsiasi filtro del predicato che modifica o mantiene lo stato dovrebbe essere l'ultima parte assoluta della definizione del predicato per garantire che modifichi lo stato solo internamente quando tutte le condizioni del predicato hanno superato la valutazione.