Prædikatrækkefølge har betydning i forlængede begivenheder

I hver præsentation, jeg holder om Extended Events, forsøger jeg at forklare en af ​​de største forskelle mellem filtrering i Extended Events og filtrering i Trace; det faktum, at prædikatrækkefølgen har betydning i udvidede arrangementer. Det meste af tiden taler jeg om kortslutning af prædikatevaluering i udvidede hændelser, og forsøger at få hændelsesprædikatet til at fejle logisk evaluering så hurtigt som muligt for at returnere kontrol til den udførende opgave. Jeg arbejdede for nylig med en af ​​mine eksempler på begivenhedssessioner, som jeg bruger i præsentationer, der demonstrerer et andet vigtigt aspekt af prædikatrækkefølgen i udvidede begivenheder.

Inden for udvidede hændelser er der tekstlige prædikatkomparatorer, der giver mulighed for mere komplekse definitioner af filtreringskriterierne for en hændelse. Nogle få af disse opretholder faktisk en intern tilstand, mens begivenhedssessionen startes på serveren, for eksempel comparatorerne package0.greater_than_max_uint64 og package0.less_than_min_uint64. Der er også et prædikatkildeelement, package0.counter, som også opretholder en intern tilstand, når begivenhedssessionen startes. For tilstanden, der opretholder prædikater i udvidede begivenheder, er en af ​​de vigtigste overvejelser, at den interne tilstand ændres, hver gang det tilstand, der opretholder prædikatet, evalueres, ikke når begivenheden udløses fuldt ud. For at demonstrere dette, lad os tage et kig på et eksempel på brug af package0.greater_than_max_uint64 tekstprædikatkomparator. Først skal vi oprette en lagret procedure, som vi kan kontrollere udførelsesvarigheden af:

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

Derefter bliver vi nødt til at oprette en hændelsessession for at spore udførelsen af ​​den lagrede procedure ved hjælp af hændelsen sqlserver.module_end, og filtrerer kørslen på kolonnerne object_id og source_database_id leveret af hændelsen. Vi vil også definere et filter ved hjælp af package0.greater_than_max_uint64 tekstlige komparator mod varighedskolonnen, som er i mikrosekunder i Extended Events, med en starttilstand på 1000000 eller et sekund. Med denne tilføjelse til prædikatet vil hændelsen kun udløses, når varigheden overstiger den oprindelige værdi på 1000000 mikrosekunder, og derefter gemmer prædikatet den nye tilstandsværdi internt, så hændelsen ikke udløses fuldt ud igen, før varigheden overstiger ny intern tilstandsværdi. Når vi først har oprettet begivenhedssessionen, som i dette tilfælde bruger Dynamic SQL, da vi ikke kan bruge parameterisering i DDL-sætninger i SQL Server, vil den blive startet på serveren, og vi kan køre vores prøvelagrede procedure og kontrollere udførelsesvarigheden flere gange at se på, hvordan begivenheden affyrede med vores prædikat.

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;

Hvis du læser min blog på SQLskills.com, ved du sikkert, at jeg ikke er en stor fan af at bruge ring_buffer-målet i Extended Events af en række årsager. For denne begrænsede dataindsamling, og det faktum, at hændelsessessionen begrænser den til maksimalt ti hændelser, er det et let mål at demonstrere adfærden af ​​hændelsesprædikatrækkefølgen, men vi skal stadig makulere XML'en for hændelserne manuelt for at se resultaterne.

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

Kørsel af koden ovenfor vil resultere i kun 2 hændelser, den ene i det ene sekund og derefter den anden i de to sekunders henrettelser. De andre eksekveringer af den lagrede procedure er kortere end det første et sekunds varighedsfilter specificeret i mikrosekunder i prædikatet, og derefter er den sidste et sekunds udførelse kortere i varighed end den lagrede tilstandsværdi på to sekunder af komparatoren. Dette er den forventede adfærd for hændelsesindsamlingen, men hvis vi ændrer prædikatrækkefølgen, så filteret package0.greater_than_max_uint64(duration, 1000000) forekommer først i prædikatrækkefølgen, og opretter en anden lagret procedure, som vi udfører med en varighed på tre sekunder først får vi ingen begivenheder overhovedet.

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;

I dette tilfælde, fordi den tilstandsbevarende komparator forekommer først i prædikatrækkefølgen, øges dens interne værdi med de tre sekunders udførelse af den anden lagrede procedure, selvom hændelsen senere svigter objekt_id-filteret for prædikatet og ikke udløses fuldt ud. Denne adfærd sker med hver eneste stat, der opretholder prædikater i udvidede begivenheder. Jeg havde tidligere opdaget denne adfærd med kildekolonnen package0.counter-prædikat, men var ikke klar over, at adfærden forekommer for nogen del af prædikatet, der opretholder en tilstand. Den interne tilstand vil ændre sig, så snart den del af prædikatet er evalueret. Af denne grund bør ethvert prædikatfilter, der ændrer eller vedligeholder tilstand, være den absolut sidste del af prædikatdefinitionen for at sikre, at det kun ændrer tilstanden internt, når alle prædikatbetingelserne har bestået evalueringen.