Predykat ma znaczenie w rozszerzonych zdarzeniach

W każdej prezentacji, którą wygłaszam na temat zdarzeń rozszerzonych, staram się wyjaśnić jedną z największych różnic między filtrowaniem w zdarzeniach rozszerzonych a filtrowaniem w Trace; fakt, że kolejność orzeczeń ma znaczenie w zdarzeniach rozszerzonych. Przez większość czasu mówię o zwarciu oceny predykatu w zdarzeniach rozszerzonych i próbie spowodowania, aby predykat zdarzenia nie powiódł logicznej oceny tak szybko, jak to możliwe, aby przywrócić kontrolę do wykonywanego zadania. Niedawno pracowałem z jedną z moich przykładowych sesji zdarzeń, której używam w prezentacjach, która demonstruje inny ważny aspekt kolejności predykatów w zdarzeniach rozszerzonych.

W ramach zdarzeń rozszerzonych znajdują się tekstowe komparatory predykatów, które pozwalają na bardziej złożone definicje kryteriów filtrowania zdarzenia. Kilka z nich faktycznie utrzymuje stan wewnętrzny podczas uruchamiania sesji zdarzenia na serwerze, na przykład komparatory package0.greater_than_max_uint64 i package0.less_than_min_uint64. Istnieje również element źródłowy predykatu, package0.counter, który również utrzymuje stan wewnętrzny po uruchomieniu sesji zdarzeń. W przypadku predykatów utrzymujących stan w zdarzeniach rozszerzonych jednym z najważniejszych rozważań jest to, że stan wewnętrzny zmienia się za każdym razem, gdy predykat utrzymujący stan jest oceniany, a nie w przypadku pełnego uruchomienia zdarzenia. Aby to zademonstrować, spójrzmy na przykładowe użycie tekstowego komparatora predykatu package0.greater_than_max_uint64. Najpierw musimy stworzyć procedurę składowaną, dzięki której będziemy mogli kontrolować czas wykonywania:

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

Następnie musimy utworzyć sesję zdarzenia, aby śledzić wykonania procedury składowanej przy użyciu zdarzenia sqlserver.module_end i przefiltrować wykonania w kolumnach object_id i source_database_id dostarczonych przez zdarzenie. Zdefiniujemy również filtr za pomocą komparatora tekstowego package0.greater_than_max_uint64 względem kolumny czasu trwania, która jest w mikrosekundach w zdarzeniach rozszerzonych, ze stanem początkowym 1000000 lub jedną sekundą. Dzięki temu dodaniu do predykatu zdarzenie zostanie uruchomione tylko wtedy, gdy czas trwania przekroczy wartość początkową 1000000 mikrosekund, a następnie predykat będzie wewnętrznie przechowywać nową wartość stanu, dzięki czemu zdarzenie nie zostanie ponownie uruchomione w pełni, dopóki czas trwania nie przekroczy nowa wartość stanu wewnętrznego. Po utworzeniu sesji zdarzenia, która w tym przypadku korzysta z Dynamic SQL, ponieważ nie możemy użyć parametryzacji w instrukcjach DDL w SQL Server, zostanie ona uruchomiona na serwerze i będziemy mogli wielokrotnie uruchamiać naszą przykładową procedurę składowaną i kontrolować czas trwania wykonania aby zobaczyć, jak zdarzenie zostało wywołane z naszym predykatem.

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;

Jeśli czytasz mojego bloga na SQLskills.com, prawdopodobnie wiesz, że nie jestem wielkim fanem używania obiektu docelowego ring_buffer w zdarzeniach rozszerzonych z wielu powodów. W przypadku tego ograniczonego gromadzenia danych oraz faktu, że sesja zdarzenia ogranicza ją do maksymalnie dziesięciu zdarzeń, łatwo jest zademonstrować zachowanie kolejności predykatów zdarzeń, ale nadal musimy ręcznie zniszczyć kod XML dla zdarzeń, aby zobacz wyniki.

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

Uruchomienie powyższego kodu spowoduje tylko 2 zdarzenia, jedno na jedną sekundę, a drugie na wykonanie dwóch sekund. Inne wykonania procedury przechowywanej są krótsze niż początkowy jednosekundowy filtr czasu trwania określony w mikrosekundach w predykacie, a ostatnie jednosekundowe wykonanie trwa krócej niż wartość stanu przechowywanego wynosząca dwie sekundy przez komparator. Jest to oczekiwane zachowanie kolekcji zdarzeń, ale jeśli zmienimy kolejność predykatów tak, aby filtr package0.greater_than_max_uint64(duration, 1000000) wystąpił jako pierwszy w kolejności predykatów i utworzymy drugą procedurę składowaną, którą wykonujemy z czasem trwania trzy sekundy pierwsze, w ogóle nie otrzymamy żadnych wydarzeń.

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;

W takim przypadku, ponieważ komparator utrzymujący stan występuje jako pierwszy w kolejności predykatów, jego wartość wewnętrzna jest zwiększana przez trzysekundowe wykonanie drugiej procedury składowanej, nawet jeśli zdarzenie później nie powiedzie się filtrem object_id predykatu i nie zostanie w pełni uruchomione. To zachowanie ma miejsce w przypadku każdego stanu utrzymującego predykaty w zdarzeniach rozszerzonych. Wcześniej wykryłem to zachowanie z kolumną źródłową predykatu package0.counter, ale nie zdawałem sobie sprawy, że zachowanie występuje dla dowolnej części predykatu, która utrzymuje stan. Stan wewnętrzny zmieni się, gdy tylko ta część predykatu zostanie oceniona. Z tego powodu każdy filtr predykatu, który zmienia lub utrzymuje stan, powinien być absolutną ostatnią częścią definicji predykatu, aby zapewnić, że modyfikuje stan wewnętrznie tylko wtedy, gdy wszystkie warunki predykatu przejdą ocenę.