Are My Triggers Being Fired?

The other day my team was asked by a developer to see if his trigger was firing. One person has been working on a Profiler Trace but I thought this would be a good opportunity to raise awareness regarding Extended Events within my team. So while I’m waiting for a good change window to be able to monitor the backup throughput of my VLDB with my backup_restore_throughput XE Session I figured I’d work something up for them.

So I created some simple test tables and triggers

CREATE TABLE dbo.base(
	base_id int IDENTITY(0,1) NOT NULL PRIMARY KEY,
	base_value varchar(25) NOT NULL
);
GO
CREATE TABLE dbo.t_target(
	target_id int IDENTITY(0,1) NOT NULL,
	base_id int NOT NULL REFERENCES dbo.base(base_id) ON DELETE CASCADE
);
GO
CREATE TABLE dbo.t_audit(
	deleted_base_id INTEGER NOT NULL, 
	deleted_base_value varchar(25) NOT NULL
);
GO
CREATE TRIGGER insert_base_trigger on dbo.base
	FOR INSERT
	AS
	BEGIN
		INSERT INTO t_target (base_id)
			SELECT base_id 
				FROM inserted;
	END
GO
CREATE TRIGGER delete_base_trigger ON dbo.base
	INSTEAD OF DELETE
	AS
	BEGIN
		INSERT INTO t_audit (deleted_base_id, deleted_base_value)
			SELECT base_id, base_value from deleted;
		DELETE b 
		FROM base b 
		join deleted d 
			on b.base_id = d.base_id;			
	END
GO		

Create the event session, filtered on the specific database (with help from Thomas Stringer, [@SQLife])

CREATE EVENT SESSION [trigger_audit] ON SERVER 
ADD EVENT sqlserver.module_end(
    WHERE ([sqlserver].[database_id]=(23))),
ADD EVENT sqlserver.module_start(
    WHERE ([sqlserver].[database_id]=(23))),
ADD EVENT sqlserver.sql_statement_completed(
    ACTION(sqlserver.server_instance_name,sqlserver.tsql_frame,sqlserver.tsql_stack,sqlserver.username)
    WHERE ([sqlserver].[database_id]=(23))),
ADD EVENT sqlserver.sql_statement_starting(
    ACTION(sqlserver.server_instance_name,sqlserver.tsql_frame,sqlserver.tsql_stack,sqlserver.username)
    WHERE ([sqlserver].[database_id]=(23))) 
ADD TARGET package0.event_file(SET filename=N'D:\temp\trigger_audit.xel')
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON,STARTUP_STATE=OFF)
GO

Run the code to fire events

ALTER EVENT SESSION trigger_audit ON SERVER
	STATE = START
GO
---Taken from Kendra Little's Table Partitioning Tutorial Script
WITH    Pass0 AS ( SELECT   1 AS C UNION ALL SELECT   1), 
	Pass1 AS ( SELECT   1 AS C FROM     Pass0 AS A , Pass0 AS B),
	Pass2 AS ( SELECT   1 AS C FROM     Pass1 AS A , Pass1 AS B),
	Pass3 AS ( SELECT   1 AS C FROM     Pass2 AS A , Pass2 AS B),
	Pass4 AS ( SELECT   1 AS C FROM     Pass3 AS A , Pass3 AS B),
	Pass5 AS ( SELECT   1 AS C FROM     Pass4 AS A , Pass4 AS B),
	tally AS ( SELECT   row_number() OVER ( Order BY C ) AS N FROM Pass5 )
--Fire FOR INSERT trigger
INSERT INTO base (base_value)
SELECT  CAST(N AS VARCHAR(25)) -- This was a really lazy way to create a value
FROM    tally
WHERE   N <= 100000;
GO
--Fire INSTEAD OF DELETE trigger
DELETE FROM base
	where base_id < 1000;
GO

ALTER EVENT SESSION trigger_audit ON SERVER
	STATE = STOP
GO

Then we can look at the Event File to see what happened.

SELECT 
 event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
 event_data.value('(event/data[@name="object_name"]/value)[1]','sysname') as object_name,
 event_data.value('(event/data[@name="object_type"]/value)[1]','sysname') as object_type,
 event_data.value('(event/data[@name="duration"]/value)[1]','bigint') as duration,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    event_data.value('(event/data[@name="statement"]/value)[1]','nvarchar(max)') as statement,    
	CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier) as activity_id,
                CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 38, 10) AS int) as event_sequence,
                CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id_xfer"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier) as activity_id_xfer,
event_data.value('(event/action[@name="username"]/value)[1]','sysname') as username
FROM (
SELECT
    CAST(event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file('D:\temp\trigger_aud*.xel', NULL, NULL, NULL)

) xe
order by timestamp

trigger_event_session

The first activity (outlined in red) is the insert. We can see that that trigger is fired (outlined in orange) as part of the same activity. The trigger execution (outlined in black) took 1029058 ms and the insert statement itself took 3074175 ms (outlined in green). We can see the same metrics for the delete statement (in light steel blue and brown, respectively).

The foreign key relationship between dbo.t_target and dbo.base did not execute as a separate module so I decided to check my counts to ensure that everything worked as expected:

SELECT COUNT(*) 
FROM dbo.base 
WHERE base_id < 1000;

SELECT COUNT(*) 
FROM dbo.t_target
WHERE base_id < 1000;

SELECT COUNT(*) 
	FROM dbo.t_audit;

confirm
The delete occurred on dbo.base (in the INSTEAD OF trigger), the foreign key relationship was enforced, and the rows were inserted into dbo.t_audit (in the INSTEAD OF trigger).

But now there’s another piece of information that I wish I had. It would have been really nice to get the transaction context for these actions. I have to ALTER the event session, dropping the events and then re-adding them with the new actions that I want:

ALTER EVENT SESSION [trigger_audit] ON SERVER 
DROP EVENT sqlserver.module_end, DROP EVENT sqlserver.module_start, DROP EVENT sqlserver.sql_statement_completed, DROP EVENT sqlserver.sql_statement_starting
ALTER EVENT SESSION [trigger_audit] ON SERVER 
ADD EVENT sqlserver.module_end(
    ACTION(sqlserver.transaction_id,sqlserver.transaction_sequence)
    WHERE ([sqlserver].[database_id]=(23))), ADD EVENT sqlserver.module_start(
    ACTION(sqlserver.transaction_id,sqlserver.transaction_sequence)
    WHERE ([sqlserver].[database_id]=(23))), ADD EVENT sqlserver.sql_statement_completed(
    ACTION(sqlserver.server_instance_name,sqlserver.transaction_id,sqlserver.transaction_sequence,sqlserver.tsql_frame,sqlserver.tsql_stack,sqlserver.username)
    WHERE ([sqlserver].[database_id]=(23))), ADD EVENT sqlserver.sql_statement_starting(
    ACTION(sqlserver.server_instance_name,sqlserver.transaction_id,sqlserver.transaction_sequence,sqlserver.tsql_frame,sqlserver.tsql_stack,sqlserver.username)
    WHERE ([sqlserver].[database_id]=(23)))
GO

I re-ran the test code, this time to DELETE where base_id < 10000 (as opposed to the 1000 in the last run). The parsing code had to be modified to include the transaction information and handle the event_sequence/timestamp collision.

SELECT 
 event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
 event_data.value('(event/data[@name="object_name"]/value)[1]','sysname') as object_name,
 event_data.value('(event/data[@name="object_type"]/value)[1]','sysname') as object_type,
 event_data.value('(event/data[@name="duration"]/value)[1]','bigint') as duration,
 event_data.value('(event/action[@name="transaction_id"]/value)[1]','bigint') as transaction_id,
 event_data.value('(event/action[@name="transaction_sequence"]/value)[1]','bigint') as transaction_sequence,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    event_data.value('(event/data[@name="statement"]/value)[1]','nvarchar(max)') as statement,    
	CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier) as activity_id,
                CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 38, 10) AS int) as event_sequence,
                CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id_xfer"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier) as activity_id_xfer,
event_data.value('(event/action[@name="username"]/value)[1]','sysname') as username
FROM (
SELECT
    CAST(event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file('D:\temp\trigger_audit_0_130300532708590000.xel', NULL, NULL, NULL)

) xe
order by timestamp, event_sequence

trigger_event_session_tx

What’s interesting is that the FOR trigger maintains a transaction_id throughout – it executes within the context of the same transaction. The INSTEAD OF trigger runs within a “separate” transaction, it’s own. This means one more test. I’m going to reverse the trigger types and rerun everything to see what kind of results I get.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s