Bei erweiterten Ereignissen ist die Reihenfolge der Prädikate wichtig

In jeder Präsentation, die ich zu Extended Events gebe, versuche ich, einen der größten Unterschiede zwischen dem Filtern in Extended Events und dem Filtern in Trace zu erklären; die Tatsache, dass die Reihenfolge der Prädikate in erweiterten Ereignissen wichtig ist. Meistens spreche ich über das Kurzschließen der Prädikatauswertung in erweiterten Ereignissen und über den Versuch, die logische Auswertung des Ereignisprädikats so schnell wie möglich zum Scheitern zu bringen, um die Kontrolle an die ausführende Aufgabe zurückzugeben. Ich habe kürzlich mit einer meiner Beispielereignissitzungen gearbeitet, die ich in Präsentationen verwende und die einen weiteren wichtigen Aspekt der Prädikatreihenfolge in erweiterten Ereignissen demonstriert.

Innerhalb von erweiterten Ereignissen gibt es Text-Prädikat-Komparatoren, die komplexere Definitionen der Filterkriterien für ein Ereignis ermöglichen. Einige davon behalten tatsächlich einen internen Zustand bei, während die Ereignissitzung auf dem Server gestartet wird, zum Beispiel die Vergleicher „package0.greater_than_max_uint64“ und „package0.less_than_min_uint64“. Es gibt auch ein Prädikat-Quellenelement, package0.counter, das auch einen internen Zustand beibehält, wenn die Ereignissitzung gestartet wird. Für die zustandserhaltenden Prädikate in erweiterten Ereignissen ist eine der wichtigsten Überlegungen, dass sich der interne Zustand ändert, wenn das zustandserhaltende Prädikat ausgewertet wird, und nicht, wenn das Ereignis vollständig ausgelöst wird. Um dies zu demonstrieren, werfen wir einen Blick auf eine beispielhafte Verwendung des textuellen Prädikatkomparators „package0.greater_than_max_uint64“. Zuerst müssen wir eine gespeicherte Prozedur erstellen, deren Ausführungsdauer wir steuern können:

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

Dann müssen wir eine Ereignissitzung erstellen, um die Ausführungen der gespeicherten Prozedur mithilfe des Ereignisses „sqlserver.module_end“ zu verfolgen und die Ausführungen anhand der vom Ereignis bereitgestellten Spalten „object_id“ und „source_database_id“ zu filtern. Wir definieren auch einen Filter mit dem Textkomparator package0.greater_than_max_uint64 für die Dauerspalte, die in erweiterten Ereignissen in Mikrosekunden angegeben ist, mit einem Anfangszustand von 1000000 oder einer Sekunde. Mit diesem Zusatz zum Prädikat wird das Ereignis nur ausgelöst, wenn die Dauer den Anfangswert von 1000000 Mikrosekunden überschreitet, und dann speichert das Prädikat den neuen Statuswert intern, sodass das Ereignis nicht erneut vollständig ausgelöst wird, bis die Dauer die überschreitet neuer interner Zustandswert. Sobald wir die Ereignissitzung erstellt haben, die in diesem Fall dynamisches SQL verwendet, da wir keine Parametrisierung in DDL-Anweisungen in SQL Server verwenden können, wird sie auf dem Server gestartet und wir können unsere gespeicherte Beispielprozedur ausführen und die Ausführungsdauer mehrmals steuern um zu sehen, wie das Ereignis mit unserem Prädikat ausgelöst wurde.

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;

Wenn Sie meinen Blog auf SQLskills.com lesen, wissen Sie wahrscheinlich, dass ich aus mehreren Gründen kein großer Fan der Verwendung des ring_buffer-Ziels in erweiterten Ereignissen bin. Für diese begrenzte Datensammlung und die Tatsache, dass die Ereignissitzung sie auf maximal zehn Ereignisse begrenzt, ist es ein einfaches Ziel, das Verhalten der Ereignisprädikatreihenfolge zu demonstrieren, aber wir müssen das XML für die Ereignisse noch manuell schreddern Sehen Sie sich die Ergebnisse an.

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

Das Ausführen des obigen Codes führt zu nur 2 Ereignissen, eines für die eine Sekunde und das andere für die zwei Sekunden Ausführung. Die anderen Ausführungen der gespeicherten Prozedur sind kürzer als der Filter für die anfängliche Dauer von einer Sekunde, der im Prädikat in Mikrosekunden angegeben ist, und dann ist die Dauer der letzten Ausführung von einer Sekunde kürzer als der gespeicherte Zustandswert von zwei Sekunden durch den Komparator. Dies ist das erwartete Verhalten der Ereignissammlung, aber wenn wir die Prädikatreihenfolge ändern, sodass der Filter „package0.greater_than_max_uint64(duration, 1000000)“ an erster Stelle in der Prädikatreihenfolge steht, und eine zweite gespeicherte Prozedur erstellen, die wir mit einer Dauer von „drei“ ausführen Sekunden zuerst erhalten wir überhaupt keine Ereignisse.

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;

Da in diesem Fall der zustandserhaltende Komparator in der Prädikatreihenfolge an erster Stelle steht, wird sein interner Wert durch die dreisekündige Ausführung der zweiten gespeicherten Prozedur erhöht, obwohl das Ereignis später den object_id-Filter des Prädikats nicht erfüllt und nicht vollständig ausgelöst wird. Dieses Verhalten tritt bei jedem der Zustandserhaltungsprädikate in erweiterten Ereignissen auf. Ich hatte dieses Verhalten zuvor bei der Quellspalte des Prädikats „package0.counter“ entdeckt, war mir aber nicht bewusst, dass das Verhalten für jeden Teil des Prädikats auftritt, der einen Zustand beibehält. Der interne Zustand ändert sich, sobald dieser Teil des Prädikats ausgewertet wird. Aus diesem Grund sollte jeder Prädikatfilter, der den Status ändert oder beibehält, der absolut letzte Teil der Prädikatdefinition sein, um sicherzustellen, dass er den Status nur intern ändert, wenn alle Prädikatbedingungen die Bewertung bestanden haben.