El orden de los predicados es importante en los eventos extendidos

En cada presentación que doy sobre Extended Events, trato de explicar una de las mayores diferencias entre filtrar en Extended Events y filtrar en Trace; el hecho de que el orden de los predicados es importante en los eventos extendidos. La mayor parte del tiempo hablo de hacer un cortocircuito en la evaluación de predicados en los eventos extendidos y tratar de hacer que el predicado del evento falle en la evaluación lógica lo más rápido posible para devolver el control a la tarea de ejecución. Hace poco estuve trabajando con una de mis sesiones de eventos de ejemplo que uso en presentaciones que demuestra otro aspecto importante del orden de los predicados en eventos extendidos.

Dentro de Extended Events hay comparadores de predicados textuales que permiten definiciones más complejas de los criterios de filtrado para un evento. Algunos de ellos mantienen un estado interno mientras se inicia la sesión del evento en el servidor, por ejemplo, los comparadores package0.greater_than_max_uint64 y package0.less_than_min_uint64. También hay un elemento fuente predicado, package0.counter, que también mantiene un estado interno cuando se inicia la sesión del evento. Para los predicados de mantenimiento de estado en eventos extendidos, una de las consideraciones más importantes es que el estado interno cambia cada vez que se evalúa el predicado de mantenimiento de estado, no cuando el evento se desencadena por completo. Para demostrar esto, echemos un vistazo a un ejemplo de uso del comparador de predicado textual package0.greater_than_max_uint64. Primero necesitaremos crear un procedimiento almacenado que podamos controlar la duración de la ejecución de:

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

Luego, necesitaremos crear una sesión de eventos para realizar un seguimiento de las ejecuciones del procedimiento almacenado mediante el evento sqlserver.module_end y filtrar las ejecuciones en las columnas object_id y source_database_id proporcionadas por el evento. También definiremos un filtro usando el comparador textual package0.greater_than_max_uint64 contra la columna de duración, que está en microsegundos en Extended Events, con un estado inicial de 1000000 o un segundo. Con esta adición al predicado, el evento solo se activará cuando la duración supere el valor inicial de 1000000 microsegundos y, a continuación, el predicado almacenará internamente el nuevo valor de estado, de modo que el evento no se activará completamente hasta que la duración supere el nuevo valor de estado interno. Una vez que creamos la sesión de eventos, que en este caso usa Dynamic SQL ya que no podemos usar la parametrización en declaraciones DDL en SQL Server, se iniciará en el servidor y podremos ejecutar nuestro procedimiento almacenado de muestra y controlar la duración de la ejecución varias veces. para ver cómo se disparó el evento con nuestro predicado.

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;

Si lee mi blog en SQLskills.com, probablemente sepa que no soy un gran fanático de usar el objetivo ring_buffer en eventos extendidos por varias razones. Para esta recopilación de datos limitada, y el hecho de que la sesión de eventos la limita a un máximo de diez eventos, es un objetivo fácil demostrar el comportamiento del orden de predicado de eventos, pero aún necesitamos triturar el XML de los eventos manualmente para ver los resultados.

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

Ejecutar el código anterior dará como resultado solo 2 eventos, uno para las ejecuciones de un segundo y luego el otro para las ejecuciones de dos segundos. Las otras ejecuciones del procedimiento almacenado son más cortas que el filtro de duración inicial de un segundo especificado en microsegundos en el predicado, y luego la última ejecución de un segundo tiene una duración más corta que el valor de estado almacenado de dos segundos por el comparador. Este es el comportamiento esperado de la colección de eventos, pero si cambiamos el orden de los predicados para que el filtro package0.greater_than_max_uint64(duration, 1000000) ocurra primero en el orden de los predicados y creamos un segundo procedimiento almacenado que ejecutamos con una duración de tres segundos primero, no obtendremos ningún evento en absoluto.

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;

En este caso, debido a que el comparador de mantenimiento de estado ocurre primero en el orden del predicado, su valor interno se incrementa por la ejecución de tres segundos del segundo procedimiento almacenado aunque el evento falle más adelante en el filtro object_id del predicado y no se active por completo. Este comportamiento ocurre con cada uno de los predicados de mantenimiento de estado en eventos extendidos. Anteriormente había descubierto este comportamiento con la columna de origen del predicado package0.counter, pero no me di cuenta de que el comportamiento ocurre para cualquier parte del predicado que mantiene un estado. El estado interno cambiará tan pronto como se evalúe esa parte del predicado. Por esta razón, cualquier filtro de predicado que cambie o mantenga el estado debe ser la última parte absoluta de la definición del predicado para garantizar que solo modifique el estado internamente cuando todas las condiciones del predicado hayan pasado la evaluación.