Predikátový řád je důležitý v rozšířených událostech

V každé prezentaci, kterou poskytnu na téma Extended Events, se snažím vysvětlit jeden z největších rozdílů mezi filtrováním v Extended Events a filtrováním v Trace; skutečnost, že v rozšířených událostech záleží na predikátovém pořadí. Většinu času mluvím o zkratování vyhodnocení predikátu v Extended Events a snažím se, aby predikát události selhal logického vyhodnocení co nejrychleji, aby se vrátilo řízení vykonávané úloze. Nedávno jsem pracoval s jednou ze svých ukázkových relací událostí, které používám v prezentacích a která demonstruje další důležitý aspekt predikátového pořadí v rozšířených událostech.

V rámci Extended Events existují textové predikátové komparátory, které umožňují složitější definice filtrovacích kritérií pro událost. Některé z nich ve skutečnosti udržují interní stav, když je relace události spuštěna na serveru, například komparátory package0.greater_than_max_uint64 a package0.less_than_min_uint64. Existuje také predikátový zdrojový prvek, package0.counter, který také udržuje vnitřní stav při zahájení relace události. U predikátů udržujících stav v rozšířených událostech je jedním z nejdůležitějších aspektů to, že vnitřní stav se mění vždy, když je vyhodnocen predikát udržující stav, nikoli když se událost plně spustí. Abychom to demonstrovali, podívejme se na příklad použití komparátoru textového predikátu package0.greater_than_max_uint64. Nejprve budeme muset vytvořit uloženou proceduru, u které můžeme řídit dobu provádění:

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

Potom budeme muset vytvořit relaci události, abychom mohli sledovat provádění uložené procedury pomocí události sqlserver.module_end, a filtruje spuštění ve sloupcích object_id a source_database_id poskytnutých událostí. Definujeme také filtr pomocí textového komparátoru package0.greater_than_max_uint64 proti sloupci trvání, který je v Extended Events v mikrosekundách, s počátečním stavem 1000000 nebo jedna sekunda. S tímto přidáním k predikátu se událost spustí pouze tehdy, když trvání překročí počáteční hodnotu 1 000 000 mikrosekund, a potom predikát interně uloží hodnotu nového stavu, takže událost se znovu plně nespustí, dokud trvání nepřekročí novou hodnotu vnitřního stavu. Jakmile vytvoříme relaci události, která v tomto případě používá dynamické SQL, protože nemůžeme použít parametrizaci v příkazech DDL na serveru SQL Server, bude spuštěna na serveru a můžeme spustit naši ukázkovou uloženou proceduru a řídit dobu trvání provádění několikrát. podívat se, jak událost vystřelila s naším predikátem.

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;

Pokud čtete můj blog na SQLskills.com, pravděpodobně víte, že nejsem velkým fanouškem používání cíle ring_buffer v Extended Events z mnoha důvodů. Pro tento omezený sběr dat a skutečnost, že relace události jej omezuje na maximálně deset událostí, je snadným cílem demonstrovat chování pořadí predikátů události, ale stále musíme ručně skartovat XML pro události. podívejte se na výsledky.

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

Spuštění výše uvedeného kódu bude mít za následek pouze 2 události, jednu na jednu sekundu a druhou na dvě sekundy provedení. Ostatní provedení uložené procedury jsou kratší než počáteční jednosekundový filtr trvání zadaný v mikrosekundách v predikátu a pak poslední jednosekundové provedení je kratší než hodnota uloženého stavu dvě sekundy komparátorem. Toto je očekávané chování kolekce událostí, ale pokud změníme pořadí predikátů tak, aby se filtr package0.greater_than_max_uint64(duration, 1000000) vyskytoval jako první v pořadí predikátů, a vytvoříme druhou uloženou proceduru, kterou provedeme s dobou trvání tři sekund, nezískáme vůbec žádné události.

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;

V tomto případě, protože se komparátor pro udržování stavu vyskytuje jako první v pořadí predikátů, jeho vnitřní hodnota se zvýší o tři sekundy provedení druhé uložené procedury, i když událost později selže ve filtru object_id predikátu a plně se nespustí. K tomuto chování dochází u každého z predikátů udržujících stav v rozšířených událostech. Toto chování jsem již dříve objevil se zdrojovým sloupcem predikátu package0.counter, ale neuvědomil jsem si, že k tomuto chování dochází u jakékoli části predikátu, která udržuje stav. Vnitřní stav se změní, jakmile je tato část predikátu vyhodnocena. Z tohoto důvodu by měl být jakýkoli predikátový filtr, který mění nebo udržuje stav, absolutně poslední částí definice predikátu, aby bylo zajištěno, že interně upraví stav pouze tehdy, když všechny podmínky predikátu projdou vyhodnocením.