A Ordem Predicativa é Importante em Eventos Estendidos

Em todas as apresentações que faço sobre Extended Events, tento explicar uma das maiores diferenças entre filtrar em Extended Events e filtrar em Trace; o fato de que a ordem dos predicados é importante em Eventos Estendidos. Na maioria das vezes, estou falando sobre o curto-circuito da avaliação de predicado em Eventos Estendidos e tentando fazer com que o predicado do evento falhe na avaliação lógica o mais rápido possível para retornar o controle à tarefa em execução. Recentemente, estava trabalhando com uma das minhas sessões de eventos de exemplo que uso em apresentações que demonstram outro aspecto importante da ordem de predicados em Eventos Estendidos.

Dentro de Eventos Estendidos existem comparadores de predicados textuais que permitem definições mais complexas dos critérios de filtragem de um evento. Alguns deles realmente mantêm um estado interno enquanto a sessão do evento é iniciada no servidor, por exemplo, os comparadores package0.greater_than_max_uint64 e package0.less_than_min_uint64. Há também um elemento de origem de predicado, package0.counter, que também mantém um estado interno quando a sessão do evento é iniciada. Para os predicados de manutenção de estado em Eventos Estendidos, uma das considerações mais importantes é que o estado interno muda sempre que o predicado de manutenção de estado é avaliado, não quando o evento é totalmente acionado. Para demonstrar isso, vamos dar uma olhada em um exemplo de uso do comparador de predicado textual package0.greater_than_max_uint64. Primeiro, precisaremos criar um procedimento armazenado que possamos controlar a duração da execução:

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

Em seguida, precisaremos criar uma sessão de evento para rastrear as execuções do procedimento armazenado usando o evento sqlserver.module_end e filtrar as execuções nas colunas object_id e source_database_id fornecidas pelo evento. Também definiremos um filtro usando o comparador textual package0.greater_than_max_uint64 em relação à coluna de duração, que está em microssegundos em Extended Events, com um estado inicial de 1000000 ou um segundo. Com essa adição ao predicado, o evento só será acionado quando a duração exceder o valor inicial de 1.000.000 microssegundos e, em seguida, o predicado armazenará o novo valor de estado internamente, para que o evento não seja acionado totalmente novamente até que a duração exceda a novo valor de estado interno. Uma vez que criamos a sessão do evento, que neste caso usa SQL dinâmico, pois não podemos usar parametrização em instruções DDL no SQL Server, ela será iniciada no servidor e podemos executar nosso procedimento armazenado de amostra e controlar a duração da execução várias vezes para ver como o evento disparou com nosso 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;

Se você lê meu blog em SQLskills.com, provavelmente sabe que não sou um grande fã de usar o destino ring_buffer em Eventos Estendidos por vários motivos. Para essa coleta de dados limitada, e o fato de a sessão do evento limitar a um máximo de dez eventos, é um alvo fácil demonstrar o comportamento da ordem de predicado do evento, mas ainda precisamos fragmentar o XML dos eventos manualmente para veja os 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);

A execução do código acima resultará em apenas 2 eventos, um para as execuções de um segundo e outro para as execuções de dois segundos. As outras execuções do procedimento armazenado são mais curtas do que o filtro inicial de duração de um segundo especificado em microssegundos no predicado e, em seguida, a última execução de um segundo é menor em duração do que o valor do estado armazenado de dois segundos pelo comparador. Esse é o comportamento esperado da coleção de eventos, mas se alterarmos a ordem do predicado para que o filtro package0.greater_than_max_uint64(duration, 1000000) ocorra primeiro na ordem do predicado e criarmos um segundo procedimento armazenado que executamos com duração de três segundos primeiro, não teremos nenhum 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;

Nesse caso, como o comparador de manutenção de estado ocorre primeiro na ordem do predicado, seu valor interno é incrementado pela execução de três segundos do segundo procedimento armazenado, mesmo que o evento falhe posteriormente no filtro object_id do predicado e não seja totalmente acionado. Esse comportamento acontece com cada um dos predicados de manutenção de estado em Eventos Estendidos. Eu já havia descoberto esse comportamento com a coluna de origem do predicado package0.counter, mas não percebi que o comportamento ocorre para qualquer parte do predicado que mantém um estado. O estado interno mudará assim que essa parte do predicado for avaliada. Por esse motivo, qualquer filtro de predicado que altere ou mantenha o estado deve ser a última parte absoluta da definição do predicado para garantir que só modifique o estado internamente quando todas as condições do predicado tiverem passado na avaliação.