Leveraging Context_Info & Extended Events for Deadlock Troubleshooting

Hellooo, yet another article related with deadlock troubleshooting for future reference.

Who hasn’t ever needed to capture value of variables passed for a stored procedure that was part of a deadlock and was the victim(or not)…?

The main objective of this article is to present an idea on how to output variables to extended events when analyzing deadlocks and not about fixing conflicts as there are many possible approaches and it is also very scenario dependent.

By the way the approach is also valid if you want to share some dynamic value(s) for your session in sys.dm_exec_requests while running batch(es) of sql code.

Demo timeee!

1st, prepare enviroment for deadlock generation:

• Create dummy tables

CREATE SCHEMA test
CREATE TABLE test.tbl_deadlock (id BIGINT PRIMARY KEY)

CREATE TABLE test.intermediate(col1 CHAR(1),col2 BIGINT)
INSERT INTO test.intermediate (col1,col2)
VALUES ('A',1001),('B',1002),('C',1003)

• Create procedure that deliberately leaves a transaction open

CREATE PROCEDURE test.proc_deadlock_1 @id bigint
AS
BEGIN
DECLARE @context_info_msg VARBINARY(128)

BEGIN TRAN
	SET @context_info_msg =  CONVERT(VARBINARY(128), (CAST(@id AS VARCHAR(128))))
	-- set ctx
	SET CONTEXT_INFO @context_info_msg
	-- actually insert
	INSERT INTO test.tbl_deadlock(id) SELECT @id
END

• Get the object_id of the created procedure (in this scenario it is 1205579333)

SELECT OBJECT_ID('test.proc_deadlock_1')

• Create Extended Events Session (i’m also including xml deadlock report, usually production systems tend to be configured to output deadlocks to errorlog using traceflags) but to have all the data we need in one single location, I’ve included it on the session bellow:

CREATE EVENT SESSION [DeadlockSample] ON SERVER 
ADD EVENT sqlserver.sp_statement_starting(
    ACTION(package0.event_sequence,package0.process_id,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.context_info,sqlserver.database_id,sqlserver.database_name,sqlserver.request_id,sqlserver.session_id,sqlserver.sql_text,sqlserver.transaction_id,sqlserver.transaction_sequence)
    WHERE ([object_id]=(1205579333))),
ADD EVENT sqlserver.xml_deadlock_report(
    ACTION(package0.process_id,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.context_info,sqlserver.database_id,sqlserver.database_name,sqlserver.sql_text,sqlserver.transaction_id,sqlserver.transaction_sequence))
ADD TARGET package0.event_file(SET filename=N'DeadlockSample',max_rollover_files=(2))
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=OFF,STARTUP_STATE=OFF)
GO
ALTER EVENT SESSION [DeadlockSample]  
ON SERVER  
STATE = start;  

At this stage, we already have everything in place to capture the variables (outputed to context_info) on our XEvents session and correlate with deadlock using the xActID aka TransactionID.

• Time to generate a deadlock and analyze the output, in this case we will mainly use GUI to simplify the demo.

1- SessionA execute:
DECLARE @var BIGINTSET @var = (SELECT col2 FROM test.intermediate WHERE col1='A')
EXEC test.proc_deadlock_1 @id = @var

2- SessionB execute:
DECLARE @var BIGINT
SET @var = (SELECT col2 FROM test.intermediate WHERE col1='B')
EXEC test.proc_deadlock_1 @id = @var

3- SessionA execute:
SELECT * FROM test.tbl_deadlock WHERE ID=1002

4- SessionC execute:
DECLARE @var BIGINT
SET @var = (SELECT col2 FROM test.intermediate WHERE col1='B')
EXEC test.proc_deadlock_1 @id = @var

5- SessionB execute:
SELECT * FROM test.tbl_deadlock WHERE id=1003

6- SessionC execute:
SELECT * FROM test.tbl_deadlock WHERE id=1001


<< Deadlock Generated>>

Deadlock generated at this stage, lets see if indeed we can debug the runtime variable of what we are looking for on our extended events session:

Open XML_Report and grab the transactionID of the deadlock victim, here we can observe the last command that was running but we have no visibility of other commands ran before this one:

Now that we have the transactionid we can dig a little deeper on our extended events session and reverse engineer the value we are looking for:

Et voilá! Hope you find it usefull, and yes, this is not the type of troubleshooting to be done on a daily basis but only in some edge cases where there is a need to have a deeper understanding if a certain behaviour is only caused/ triggered when some variable(s) have certain values.

All the best!

Paulo Condeça