Les questions d'ordre de prédicat dans les événements étendus

Dans chaque présentation que je donne sur les événements étendus, j'essaie d'expliquer l'une des plus grandes différences entre le filtrage dans les événements étendus et le filtrage dans Trace ; le fait que l'ordre des prédicats compte dans les événements étendus. La plupart du temps, je parle de court-circuiter l'évaluation du prédicat dans les événements étendus et d'essayer de faire échouer l'évaluation logique du prédicat d'événement aussi rapidement que possible pour redonner le contrôle à la tâche en cours d'exécution. J'ai récemment travaillé avec l'un de mes exemples de sessions d'événements que j'utilise dans des présentations qui illustrent un autre aspect important de l'ordre des prédicats dans les événements étendus.

Dans les événements étendus, il existe des comparateurs de prédicats textuels qui permettent des définitions plus complexes des critères de filtrage d'un événement. Quelques-uns d'entre eux conservent en fait un état interne pendant le démarrage de la session d'événements sur le serveur, par exemple les comparateurs package0.greater_than_max_uint64 et package0.less_than_min_uint64. Il existe également un élément source de prédicat, package0.counter, qui maintient également un état interne lorsque la session d'événements est démarrée. Pour les prédicats de maintien d'état dans les événements étendus, l'une des considérations les plus importantes est que l'état interne change chaque fois que le prédicat de maintien d'état est évalué, et non lorsque l'événement se déclenche complètement. Pour le démontrer, examinons un exemple d'utilisation du comparateur de prédicat textuel package0.greater_than_max_uint64. Nous devons d'abord créer une procédure stockée dont nous pouvons contrôler la durée d'exécution :

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

Ensuite, nous devrons créer une session d'événement pour suivre les exécutions de la procédure stockée à l'aide de l'événement sqlserver.module_end, et filtrer les exécutions sur les colonnes object_id et source_database_id fournies par l'événement. Nous définirons également un filtre à l'aide du comparateur textuel package0.greater_than_max_uint64 par rapport à la colonne de durée, qui est en microsecondes dans les événements étendus, avec un état initial de 1000000 ou une seconde. Avec cet ajout au prédicat, l'événement ne se déclenchera que lorsque la durée dépasse la valeur initiale de 1000000 microsecondes, puis le prédicat stockera la nouvelle valeur d'état en interne, de sorte que l'événement ne se déclenche pas complètement jusqu'à ce que la durée dépasse le nouvelle valeur d'état interne. Une fois que nous avons créé la session d'événements, qui dans ce cas utilise Dynamic SQL puisque nous ne pouvons pas utiliser le paramétrage dans les instructions DDL dans SQL Server, elle sera démarrée sur le serveur et nous pourrons exécuter notre exemple de procédure stockée et contrôler la durée d'exécution plusieurs fois. pour voir comment l'événement s'est déclenché avec notre prédicat.

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;

Si vous lisez mon blog sur SQLskills.com, vous savez probablement que je ne suis pas un grand fan de l'utilisation de la cible ring_buffer dans les événements étendus pour un certain nombre de raisons. Pour cette collecte de données limitée, et le fait que la session d'événements la limite à un maximum de dix événements, il est facile de démontrer le comportement de l'ordre des prédicats d'événement, mais nous devons encore détruire manuellement le XML des événements pour voir les résultats.

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

L'exécution du code ci-dessus entraînera seulement 2 événements, un pour une seconde, puis l'autre pour les deux secondes d'exécution. Les autres exécutions de la procédure stockée sont plus courtes que le filtre de durée initial d'une seconde spécifié en microsecondes dans le prédicat, puis la dernière exécution d'une seconde est plus courte que la valeur d'état stockée de deux secondes par le comparateur. C'est le comportement attendu de la collection d'événements, mais si nous modifions l'ordre des prédicats afin que le filtre package0.greater_than_max_uint64(duration, 1000000) se produise en premier dans l'ordre des prédicats et que nous créons une deuxième procédure stockée que nous exécutons avec une durée de trois secondes d'abord, nous n'obtiendrons aucun événement.

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;

Dans ce cas, étant donné que le comparateur de maintien d'état apparaît en premier dans l'ordre du prédicat, sa valeur interne est incrémentée par les trois secondes d'exécution de la deuxième procédure stockée, même si l'événement échoue ultérieurement au filtre object_id du prédicat et ne se déclenche pas complètement. Ce comportement se produit avec chacun des prédicats de maintien d'état dans les événements étendus. J'avais déjà découvert ce comportement avec la colonne source du prédicat package0.counter, mais je n'avais pas réalisé que le comportement se produit pour n'importe quelle partie du prédicat qui maintient un état. L'état interne changera dès que cette partie du prédicat sera évaluée. Pour cette raison, tout filtre de prédicat qui change ou maintient l'état doit être la dernière partie absolue de la définition de prédicat pour s'assurer qu'il ne modifie l'état en interne que lorsque toutes les conditions de prédicat ont réussi l'évaluation.