CONTEXT_INFO to get from which procedure was trigger invoked

My colleague asked me once if there is a possibility to get info in trigger, from which stored procedure was trigger invoked. That time I didn’t have answer but now I had to resolve similar task and I found it very useful. We have a table which is getting data and their modifications from many places, since there are lots of mechanisms in the game. There is direct approach from applications, databases, SSIS packages etc. APP_NAME () function was not sufficient solution in my case since there were more ways to modify data from one application. My task was to log info regarding one concrete mechanism changing data in that table. I saw on internet few samples with CONTEXT_INFO solution and I found it very useful since the mechanism is implemented in database stored procedure. Solution was very easy then:
I put something similar to script bellow to stored procedure changing data on the table

DECLARE @context SYSNAME  = 'SOMEINFO'
DECLARE @contextBIN VARBINARY(128)  = CAST ( @context AS VARBINARY(128) ) 


In database trigger logging changes, I just put following code to get stored data in CONTEXT_INFO.

SELECT CAST (CONTEXT_INFO() AS SYSNAME) FROM inserted

SET CONTEXT_INFO establishes information with current session or connection, could be used for other scenarios, e. g. passing info between nested procedures, adding more details to batches called from applications, etc. See more info here: https://bit.ly/2Kzh1Pl.

Do you have another scenarios how to use CONTEXT_INFO ?

Monitoring Deadlocks With Extended Events

With Extended events you can monitor and analyse occurence of deadlocks. Like traces there is a possibility to get information about deadlock occured in system. Lets have a look on it in detail in this post.

Lets create event session to monitor our deadlock.

CREATE EVENT SESSION DeadLockSession ON SERVER 
    ADD EVENT sqlserver.xml_deadlock_report  -- ,
      (
      ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.database_id,sqlserver.username)
       /*Filter error no or db number*/
     )   
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096 
    ) 
WITH (max_dispatch_latency = 30 seconds)

Starting esssion:

ALTER EVENT SESSION  DeadLockSession ON SERVER
STATE = START

Now I create structures, two tables,  and fill them with data. I will use it to raise a deadlock.

CREATE TABLE dbo.ConcurentTest (id INT IDENTITY(1,1))
ALTER TABLE dbo.ConcurentTest ADD col INT
CREATE TABLE dbo.ConcurentTest2 (id INT IDENTITY(1,1))
ALTER TABLE dbo.ConcurentTest2 ADD col INT
INSERT INTO dbo.ConcurentTest(col) SELECT 1 FROM sys.objects
INSERT INTO dbo.ConcurentTest2 (col) SELECT 1 FROM sys.objects

To create deadlock open two query windows in management studio and run queries (updates on tables) in bellow mentioned scripts in order specified in table bellow. We cause that queries will block each other to complete its operation because of U and X locks on our objects.

Query1

BEGIN TRAN
UPDATE dbo.ConcurentTest SET col=4 
WhERE id = 5
UPDATE dbo.ConcurentTest2 SET col=4 
WhERE id = 8
COMMIT

Query2

BEGIN TRAN
UPDATE dbo.ConcurentTest2 SET col=4 
WhERE id = 6
UPDATE dbo.ConcurentTest SET col=10
WhERE id = 7
COMMIT

Order to run queries.

OrderScript1Script2
1BEGIN TRAN
UPDATE dbo.ConcurentTest SET col=4
WhERE id = 5
2BEGIN TRAN
UPDATE dbo.ConcurentTest2 SET col=4
WhERE id = 6
3
UPDATE dbo.ConcurentTest2 SET col=4
WhERE id = 8
4
UPDATE dbo.ConcurentTest SET col=10
WhERE id = 7

Now , in one of your query window you should see deadlock message. Query in this window was marked as deadlock victim and will not finish. Updates in the other query windows will be executed and data will be updated.

Now take a look on output from extended event xml_deadlock_report.

Put data to temporary table

IF OBJECT_ID('tempdb.dbo.#LogData') IS NOT NULL
 DROP TABLE #LogData;
SELECT
       CAST(LocksAcquired.TargetXml AS XML)  AS XMLData
   INTO
       #LogData
   FROM
       (
       SELECT
               CAST(t.target_data AS XML)  AS TargetXml 
           FROM
                    sys.dm_xe_session_targets  AS t
               JOIN sys.dm_xe_sessions         AS s
                   ON s.address = t.event_session_address
           WHERE
            
               s.name        = 'DeadLockSession'
       )
     LocksAcquired

Lets parse data.

SELECT p.XMLData.value('(inputbuf)[1]', 'varchar(1000)' ) AS [SqlText] ,
   p.XMLData.value('(@lockMode)[1]', 'varchar(1000)' ) AS [LockMode],
   p.XMLData.value('(@isolationlevel)[1]', 'varchar(1000)' ) AS [IsolationLevel],
   p.XMLData.value('(@spid)[1]', 'varchar(1000)' ) AS [SPID],
   p.XMLData.value('(@id)[1]', 'varchar(1000)' ) AS [processID]
  FROM #LogData tt
CROSS APPLY XMLData.nodes('/RingBufferTarget/event[@name="xml_deadlock_report"]') AS T(XMLData) 
CROSS APPLY T.XMLData.nodes('data/value/deadlock/process-list') AS i(XMLData) 
CROSS APPLY i.XMLData.nodes('process') AS p(XMLData) 

 SELECT	 p.XMLData.value('(@objectname)[1]', 'varchar(1000)' ) AS [OwnerObjectName] 
   ,p.XMLData.value('(owner-list/owner/@id)[1]', 'varchar(1000)' ) AS [OwnerProcessId] 
   ,p.XMLData.value('(waiter-list/waiter/@id)[1]', 'varchar(1000)' ) AS [WaiterProcessId] 
  FROM #LogData tt
CROSS APPLY XMLData.nodes('/RingBufferTarget/event[@name="xml_deadlock_report"]') AS T(XMLData) 
CROSS APPLY T.XMLData.nodes('data/value/deadlock/resource-list') AS i(XMLData) 
CROSS APPLY i.XMLData.nodes('ridlock') AS p(XMLData) 

 SELECT  i.XMLData.value('(victimProcess/@id)[1]', 'varchar(1000)' ) AS [VictimProcessId] 
 FROM #LogData tt
CROSS APPLY XMLData.nodes('/RingBufferTarget/event[@name="xml_deadlock_report"]') AS T(XMLData) 
CROSS APPLY T.XMLData.nodes('data/value/deadlock/victim-list') AS i(XMLData)

After running scipts above you should see which process was evaluated as deadlock victim, marked on picture bellow. You can get queries causing deadlocks with their SPIDSs. There are more interesting informations like deadlock type. In our case it was RID lock since we dont have any index on our structures and page the query touches.

As you can see extended events are very handful in deadlocks scenarios. Since I am still addicting to extended events deeper and deeper you can look forward to another posts with this topic.

Extended events – max dispatch latency


MAX_DISPATCH_LATENCY as extended event session property – Specifies the amount of time that events are buffered in memory before being dispatched to event session targets. States in MSDN see link https://bit.ly/33He9Zt. The default for this value for this option is 30 seconds, and when you set it to 0 buffers are flushed to targets when they are full, or session is closed.

Let’s make a test, how we can check this behaviour. Here you can check in buffer_processed_count attribute how many times were buffer flushed to target. Let’s go to prove this behaviour.

Summary:

  • Let’s start extended events session and configure it for with max_dispatch_latency 1 seconds, I will use Ring Buffer as the target
  • There will be running script for 30 seconds and each second there will be raised user message to the system
  • With above mentioned configuration we will find 30 in buffer_processed_count because buffer is flushed each 1 second so it will be called 30 times
  • Clear session, create it again with changed configuration for max_dispatch_latency 30 seconds
  • Now you should see 1 in buffer_processed_count buffer is flushed each 30 seconds, our script runs for 30 seconds, there it comes with 1
  • Buffer is flushed to target when user calls

Query to get buffer_processed_count bellow 

SELECT s.buffer_processed_count,s.name,s.total_regular_buffers,s.regular_buffer_size,s.total_large_buffers,s.large_buffer_size,s.dropped_event_count,s.dropped_buffer_count,ss.largest_event_dropped_size
FROM sys.dm_xe_sessions
AS s;

Script bellow lasts 30 seconds and each second there is raised user message.

 DECLARE @Message VARCHAR(100)  
DECLARE @i INT = 0
DECLARE @sql VARCHAR(30)=''
WHILE @i <30
BEGIn
    SET @sql= 'SELECT ' + CAST (@i AS VARCHAR(20))
    SET @Message='Hello '+ CAST (@i AS VARCHAR(20) )+' '+CONVERT(VARCHAR(20),GETDATE(),120)
    RAISERROR( @Message,1,1);
    EXEC (@sql)
    WAITFOR DELAY '00:00:01'
   SET @i=@i+1
END

Let’s start session. 

CREATE EVENT SESSION TestSession ON SERVER ADD EVENT sqlserver.error_reported
(
ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.database_id,sqlserver.username)
WHERE sqlserver.database_id = 21 AND [error_number]=50000
)
ADD TARGET package0.ring_buffer (SET max_memory = 4096 ) WITH (max_dispatch_latency =1 seconds)
ALTER EVENT SESSION TestSession ON SERVER STATE = START

Here you can see that target was accessed 30 times.

Buffer processed count
Buffer processed count

Clean the session 

IF EXISTS (SELECT NULL FROM sys.server_event_sessions WHERE name = 'TestSession')
BEGIN
DROP EVENT SESSION TestSession ON SERVER;
END

Run it again with changed attribute max_dispatch_latency =30 seconds. Bellow you can see that target was accessed only 1 time.

Buffer processed count
Buffer processed count

Beware of that the counter changes in cases you access targets manually with script bellow.

IF OBJECT_ID('tempdb.dbo.#LogData') IS NOT NULL
DROP TABLE #LogData;
SELECT CAST(LocksAcquired.TargetXml AS XML) AS XMLData
INTO #LogData 
FROM (SELECT CAST(t.target_data AS XML) AS TargetXml 
FROM sys.dm_xe_session_targets AS t
JOIN sys.dm_xe_sessions AS s ON s.address = t.event_session_address
WHERE s.name='TestSession'
) AS LocksAcquired;
SELECT T.XMLData.value('(action[@name="sql_text"])[1]', 'varchar(1000)' ) AS [SqlText],
       T.XMLData.value('(@timestamp)[1]', 'datetime' )AS [OccurredDtTm],
       T.XMLData.value('(data[@name="message"])[1]','varchar(60)' ) AS [Message]
FROM #LogData CROSS APPLY XMLData.nodes('/RingBufferTarget/event[@name="error_reported"]') AS T(XMLData);