Urutan Predikat Penting dalam Acara yang Diperpanjang

Dalam setiap presentasi yang saya berikan tentang Extended Events, saya mencoba dan menjelaskan salah satu perbedaan terbesar antara filtering di Extended Events dan filtering di Trace; fakta bahwa urutan predikat penting dalam Acara yang Diperpanjang. Sebagian besar waktu saya berbicara tentang hubungan arus pendek evaluasi predikat di Acara yang Diperpanjang, dan mencoba membuat predikat acara gagal evaluasi logis secepat mungkin untuk mengembalikan kontrol ke tugas pelaksana. Baru-baru ini saya bekerja dengan salah satu contoh sesi acara yang saya gunakan dalam presentasi yang menunjukkan aspek penting lain dari urutan predikat di Acara yang Diperpanjang.

Dalam Acara yang Diperpanjang ada pembanding predikat tekstual yang memungkinkan definisi yang lebih kompleks dari kriteria pemfilteran untuk suatu acara. Beberapa di antaranya benar-benar mempertahankan status internal saat sesi acara dimulai di server, misalnya package0.greater_than_max_uint64 dan package0.less_than_min_uint64 komparator. Ada juga elemen sumber predikat, package0.counter, yang juga mempertahankan status internal saat sesi acara dimulai. Untuk predikat yang mempertahankan status dalam Peristiwa yang Diperpanjang, salah satu pertimbangan terpenting adalah bahwa status internal berubah setiap kali status yang mempertahankan predikat dievaluasi, bukan saat peristiwa sepenuhnya diaktifkan. Untuk mendemonstrasikan ini, mari kita lihat contoh penggunaan komparator predikat tekstual package0.greater_than_max_uint64. Pertama, kita perlu membuat prosedur tersimpan yang dapat kita kendalikan durasi eksekusinya:

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

Kemudian kita perlu membuat sesi acara untuk melacak eksekusi prosedur tersimpan menggunakan acara sqlserver.module_end, dan memfilter eksekusi pada kolom object_id dan source_database_id yang disediakan oleh acara. Kami juga akan mendefinisikan filter menggunakan komparator teks package0.greater_than_max_uint64 terhadap kolom durasi, yang dalam mikrodetik dalam Peristiwa yang Diperpanjang, dengan status awal 1000000 atau satu detik. Dengan penambahan predikat ini, event hanya akan menyala jika durasinya melebihi nilai awal 1000000 mikrodetik, kemudian predikat akan menyimpan nilai state baru secara internal, sehingga event tidak menyala kembali sepenuhnya hingga durasi melebihi durasi. nilai keadaan internal baru. Setelah kami membuat sesi acara, yang dalam hal ini menggunakan SQL Dinamis karena kami tidak dapat menggunakan parameterisasi dalam pernyataan DDL di SQL Server, itu akan dimulai di server dan kami dapat menjalankan prosedur tersimpan sampel kami dan mengontrol durasi eksekusi beberapa kali untuk melihat bagaimana peristiwa itu dipicu dengan predikat kami.

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;

Jika Anda membaca blog saya di SQLskills.com, Anda mungkin tahu bahwa saya bukan penggemar berat menggunakan target ring_buffer di Acara yang Diperpanjang karena sejumlah alasan. Untuk pengumpulan data yang terbatas ini, dan fakta bahwa sesi acara membatasinya hingga maksimum sepuluh peristiwa, ini adalah target yang mudah untuk mendemonstrasikan perilaku urutan predikat peristiwa, tetapi kita masih perlu menghancurkan XML untuk peristiwa secara manual untuk lihat hasilnya.

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

Menjalankan kode di atas hanya akan menghasilkan 2 kejadian, satu untuk satu detik, dan yang lainnya untuk dua detik eksekusi. Eksekusi lain dari prosedur tersimpan lebih pendek dari filter durasi satu detik awal yang ditentukan dalam mikrodetik dalam predikat, dan kemudian eksekusi satu detik terakhir lebih pendek durasinya daripada nilai status tersimpan dua detik oleh komparator. Ini adalah perilaku yang diharapkan dari kumpulan peristiwa, tetapi jika kita mengubah urutan predikat sehingga filter package0.greater_than_max_uint64(duration, 1000000) muncul pertama kali dalam urutan predikat, dan membuat prosedur tersimpan kedua yang kita jalankan dengan durasi tiga detik pertama, kita tidak akan mendapatkan event sama sekali.

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;

Dalam kasus ini, karena komparator pemelihara keadaan terjadi pertama kali dalam urutan predikat, nilai internalnya bertambah dengan eksekusi tiga detik dari prosedur tersimpan kedua meskipun peristiwa tersebut kemudian gagal filter object_id dari predikat dan tidak sepenuhnya diaktifkan. Perilaku ini terjadi dengan setiap status mempertahankan predikat di Acara yang Diperpanjang. Saya sebelumnya telah menemukan perilaku ini dengan kolom sumber predikat package0.counter, tetapi tidak menyadari bahwa perilaku tersebut terjadi untuk bagian mana pun dari predikat yang mempertahankan status. Keadaan internal akan berubah segera setelah bagian predikat itu dievaluasi. Karena alasan ini, filter predikat apa pun yang mengubah atau mempertahankan status harus menjadi bagian terakhir mutlak dari definisi predikat untuk memastikan filter tersebut hanya mengubah status secara internal ketika semua kondisi predikat telah lulus evaluasi.