拡張イベントでの述語注文の問題

拡張イベントに関するすべてのプレゼンテーションで、拡張イベントでのフィルタリングとトレースでのフィルタリングの最大の違いの1つを説明しようとしています。拡張イベントでは、述語の順序が重要であるという事実。ほとんどの場合、拡張イベントでの述語評価の短絡について話し、イベント述語を論理評価にできるだけ早く失敗させて、実行中のタスクに制御を戻そうとしています。私は最近、拡張イベントでの述語順序の別の重要な側面を示すプレゼンテーションで使用するイベントセッションの例の1つを使用していました。

拡張イベント内には、イベントのフィルタリング基準のより複雑な定義を可能にするテキスト述語コンパレータがあります。これらのいくつかは、実際には、サーバーでイベントセッションが開始されている間、内部状態を維持します。たとえば、package0.greater_than_max_uint64およびpackage0.less_than_min_uint64コンパレーターです。イベントセッションの開始時に内部状態を維持する述語ソース要素package0.counterもあります。拡張イベントの状態維持述部の場合、最も重要な考慮事項の1つは、イベントが完全に発生したときではなく、状態維持述部が評価されるたびに内部状態が変化することです。これを実証するために、package0.greater_than_max_uint64テキスト述語コンパレータの使用例を見てみましょう。まず、次の実行期間を制御できるストアドプロシージャを作成する必要があります。

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

次に、sqlserver.module_endイベントを使用してストアドプロシージャの実行を追跡するイベントセッションを作成し、イベントによって提供されるobject_id列とsource_database_id列で実行をフィルタリングする必要があります。また、package0.greater_than_max_uint64テキストコンパレータを使用して、期間列に対してフィルタを定義します。これは、拡張イベントではマイクロ秒単位で、初期状態は1000000または1秒です。この述語への追加により、イベントは期間が1000000マイクロ秒の初期値を超えた場合にのみ発生し、その後、述部は新しい状態値を内部に格納するため、期間が期間を超えるまでイベントは完全に再度発生しません。新しい内部状態値。イベントセッションを作成すると（この場合、SQL ServerのDDLステートメントでパラメーター化を使用できないため動的SQLを使用します）、サーバー上で開始され、サンプルのストアドプロシージャを実行して、実行期間を複数回制御できます。イベントがどのように述語で発生したかを確認します。

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;

SQLskills.comで私のブログを読んだら、私が拡張イベントでring_bufferターゲットを使用することの大ファンではないことをおそらくご存知でしょう。この限られたデータ収集と、イベントセッションで最大10個のイベントに制限されているという事実から、イベント述語の順序の動作を示すのは簡単なターゲットですが、イベントのXMLを手動で細断処理す​​る必要があります。結果を確認してください。

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

上記のコードを実行すると、2つのイベントが発生します。1つは1秒間、もう1つは2秒間の実行です。ストアドプロシージャの他の実行は、述部でマイクロ秒単位で指定された最初の1秒の継続時間フィルターよりも短く、最後の1秒間の実行は、コンパレーターによって保存された状態値2秒よりも継続時間が短くなります。これはイベントコレクションの予想される動作ですが、述語の順序を変更して、package0.greater_than_max_uint64（duration、1000000）フィルターが最初に述語の順序で発生し、3つの期間で実行する2番目のストアドプロシージャを作成するとします。最初の数秒は、イベントをまったく取得しません。

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;

この場合、状態維持コンパレーターは述語の順序で最初に発生するため、イベントが後で述語のobject_idフィルターに失敗し、完全に起動しなくても、その内部値は2番目のストアード・プロシージャーの3秒の実行によって増分されます。この動作は、拡張イベントで述語を維持しているすべての状態で発生します。私は以前にpackage0.counter述語ソース列でこの動作を発見しましたが、状態を維持する述語のどの部分でも動作が発生することに気づいていませんでした。述語のその部分が評価されるとすぐに、内部状態が変化します。このため、状態を変更または維持する述語フィルターは、すべての述語条件が評価に合格したときにのみ内部的に状態を変更するように、述語定義の絶対的な最後の部分にする必要があります。