Systems Engineering and RDBMS

Interpreting deadlock trace output in SQL Server

Posted by decipherinfosys on January 21, 2007

A SQL Server Profiler trace has a lock event for “deadlock” and for “deadlock chain.” “Deadlock” corresponds to the -T1204 flag, and “deadlock chain” corresponds to the -T1205 flag. Turning on the deadlock trace flags and running a SQL Profiler trace during the occurrence of a deadlock should provide you the data that you must have to troubleshoot a deadlock. Once you have captured the trace output, here is how you can analyze it. What is shown below is a sample deadlock trace file that we obtained for our analysis while working on a project and this trace file was due to a deadlock chain with multiple resources involved in the deadlock.

Deadlock encountered …. Printing deadlock information
2005-03-30 14:36:41.66 spid4
2005-03-30 14:36:41.66 spid4 Wait-for graph
2005-03-30 14:36:41.66 spid4
2005-03-30 14:36:41.66 spid4 Node:1
2005-03-30 14:36:41.66 spid4 KEY: 8:1237579447:19 (aa00767285d9) CleanCnt:1 Mode: X Flags: 0×0
2005-03-30 14:36:41.66 spid4 Grant List 0::
2005-03-30 14:36:41.66 spid4 Owner:0x68bb5ba0 Mode: X Flg:0×0 Ref:0 Life:02000000 SPID:145 ECID:0
2005-03-30 14:36:41.66 spid4 SPID: 145 ECID: 0 Statement Type: EXECUTE Line #: 1
2005-03-30 14:36:41.66 spid4 Input Buf: RPC Event: sp_cursorfetch;1
2005-03-30 14:36:41.66 spid4 Requested By:
2005-03-30 14:36:41.66 spid4 ResType:LockOwner Stype:’OR’ Mode: U SPID:112 ECID:0 Ec:(0x7132F5A0) Value:0x6da4e440 Cost:(0/C7C)
2005-03-30 14:36:41.66 spid4
2005-03-30 14:36:41.66 spid4 Node:2
2005-03-30 14:36:41.66 spid4 KEY: 8:539148966:2 (7401adef8c32) CleanCnt:1 Mode: U Flags: 0×0
2005-03-30 14:36:41.66 spid4 Grant List 2::
2005-03-30 14:36:41.66 spid4 Owner:0x76b5b700 Mode: U Flg:0×0 Ref:0 Life:02000000 SPID:139 ECID:0
2005-03-30 14:36:41.66 spid4 SPID: 139 ECID: 0 Statement Type: EXECUTE Line #: 1
2005-03-30 14:36:41.66 spid4 Input Buf: RPC Event: sp_cursorfetch;1
2005-03-30 14:36:41.66 spid4 Requested By:
2005-03-30 14:36:41.66 spid4 ResType:LockOwner Stype:’OR’ Mode: U SPID:145 ECID:0 Ec:(0x7C5715B0) Value:0x7c95c5a0 Cost:(0/6D8)
2005-03-30 14:36:41.66 spid4
2005-03-30 14:36:41.66 spid4 Node:3
2005-03-30 14:36:41.66 spid4 KEY: 8:539148966:2 (7901d0a7a3ff) CleanCnt:1 Mode: U Flags: 0×0
2005-03-30 14:36:41.66 spid4 Grant List 3::
2005-03-30 14:36:41.66 spid4 Owner:0x6da4efc0 Mode: U Flg:0×0 Ref:0 Life:02000000 SPID:112 ECID:0
2005-03-30 14:36:41.66 spid4 SPID: 112 ECID: 0 Statement Type: UPDATE Line #: 1
2005-03-30 14:36:41.66 spid4 Input Buf: RPC Event: sp_executesql;1
2005-03-30 14:36:41.66 spid4 Requested By:
2005-03-30 14:36:41.66 spid4 ResType:LockOwner Stype:’OR’ Mode: U SPID:139 ECID:0 Ec:(0x767D55A0) Value:0x76b5b740 Cost:(0/0)
2005-03-30 14:36:41.66 spid4 Victim Resource Owner:
2005-03-30 14:36:41.66 spid4 ResType:LockOwner Stype:’OR’ Mode: U SPID:139 ECID:0 Ec:(0x767D55A0) Value:0x76b5b740 Cost:(0/0)
2005-03-30 14:36:41.66 spid4

So, what can you infer from this graph ? Pretty cryptic, isn’t it?

Here is how you can troubleshoot it :

Node represents the entry number in the deadlock chain…in this graph, there are three spids in the deadlock chain.

SPID: x ECID: x

Identifies the system process ID thread in cases of parallel processes. The entry SPID x ECID 0 represents the main thread, and SPID x ECID > 0 represents the sub-threads for the same SPID. In our case, it is the main thread in all three.

Statement Type: Represents update, select, insert, delete, execute (execute in our case is because of the server side cursors)…and the update is for one of the spids.

Mode: This is the lock mode that was granted for that spid – too detailed to explain in a blog entry (refer to BOL for the lock modes).

All the locks in this case are related to KEY.

KEY identifies the key range within an index on which a lock is held or requested.

KEY is represented KEY: db_id:object_id:index_id; So, for:

1) SPID 145: DB_ID = 8, object_id = 1237579447 and index_id=19

2) SPID 139: DB_ID = 8, object_id = 539148966 and index_id=2

3) SPID 112: DB_ID = 8, object_id = 539148966 and index_id=2

By running this in Query Analyzer(SQL 2000) / Management Studio (SQL 2005) against the database :

select db_name(8) — you will get the database name
select object_name(237579447)
–replace the other one as well, you will get the object-name

For getting the index information, you can use the sp_helpindex command

Basically what happened in this deadlock was this:

· Spid 145 is blocked on its request for an Update (U) lock on a record in the table with ID = 539148966 because spid 139 has an Update (U) lock on it.

· Spid 112 is blocked from its request for an Update (U) lock on a record in the table with ID = 1237579447 because spid 145 has an exclusive (X) lock on it.

· Spid 139 is blocked on its request for an Update (U) lock on a record in the table with ID = 539148966 because spid 112 has an Update (U) lock on it.

· Spid 139 was chosen as the deadlock victim by the engine and it’s transaction work was rolled back as a part of the deadlock.

The entire chain of commands are not reported in deadlock traces but the actual contention points are reported since this occurs as a snapshot at the time when the deadlock occurs. In this case, there is a chain of three spids each waiting on a resource. In order to break the deadlock, one in the chain had to be rolled back…here is a simplified diagram:

table.JPG
Handling Deadlocks in the application

When a transaction submitted by an application is chosen as the deadlock victim, the transaction is terminated automatically and rolled back, and an error message 1205 is returned to the application. Because any application submitting SQL queries can be chosen as the deadlock victim (depending upon the unit of work done by that spid), applications should have an error handler that can trap error message 1205. If an application does not trap the error, it can proceed unaware that its transaction has been rolled back, and errors can occur.

Implementing an error handler that traps error message 1205 allows an application to handle the deadlock situation and take remedial action (for example, automatically resubmitting the query that was involved in the deadlock or having a timer logic for re-trying the queries n number of times). Resubmitting the query automatically can provide very good end user experience since this means that the user does not need to know that a deadlock occurred since the application can handle the situation more gracefully.

In SQL Server 2005, you can implement TRY-CATCH blocks in your T-SQL database code in order to trap the deadlock error. An example of this is given in the code sample below.

CREATE SCHEMA MY_TEST
go
CREATE TABLE MY_TEST.tbl_author
(id INT IDENTITY(1,1) PRIMARY KEY, Author_name VARCHAR(128) not null)
go
INSERT INTO MY_TEST.tbl_author (Author_Name) VALUES(‘Bill King’)
INSERT INTO MY_TEST.tbl_author (Author_Name) VALUES(‘Henk Master’)
go

/* SESSION #1 */
DECLARE @retry INT
SET @retry = 5 /* number of retries */
WHILE (@retry > 0)
BEGIN
BEGIN TRY
BEGIN TRANSACTION
UPDATE MY_TEST.tbl_author SET Author_Name=’Robert Baitis’ WHERE id = 1
WAITFOR DELAY ’00:00:10′
UPDATE MY_TEST.tbl_author SET Author_Name=’Dennis Castaldi’ WHERE id = 2
SET @retry=-1
END TRY
BEGIN CATCH
if (error_number() = 1205)
SET @retry=@retry-1 /*retry*/
else
SET @retry=-1 /*not a deadlock*/
PRINT ERROR_NUMBER()
PRINT ERROR_SEVERITY()
PRINT ERROR_MESSAGE()
PRINT ERROR_STATE()
PRINT XACT_STATE()
if (@@trancount>0)
ROLLBACK TRANSACTION
END CATCH
END
IF (@@trancount>0)
COMMIT TRANSACTION

/* SESSION #2*/
DECLARE @retry INT
SET @retry = 5 /* number of retries*/
WHILE (@retry > 0)
BEGIN
BEGIN TRY
BEGIN TRANSACTION
UPDATE MY_TEST.tbl_author SET Author_Name=’Ken Shipp’ WHERE id = 2
WAITFOR DELAY ’00:00:10′
UPDATE MY_TEST.tbl_author SET Author_Name=’Nimish Sevak’ WHERE id = 1
SET @retry=-1
END TRY
BEGIN CATCH
if (error_number() = 1205)
SET @retry=@retry-1 /*retry*/
else
SET @retry=-1 /*not a deadlock*/
PRINT ERROR_NUMBER()
PRINT ERROR_SEVERITY()
PRINT ERROR_MESSAGE()
PRINT ERROR_STATE()
PRINT XACT_STATE()
if (@@trancount>0)
ROLLBACK TRANSACTION
END CATCH
END
IF (@@trancount>0)
COMMIT TRANSACTION

You will notice that one of the sessions will encounter the deadlock error and you can check the final values in the table by using this SQL:

select * from MY_TEST.tbl_author
go

TRY-CATCH block adds a lot of flexibility as well as robust error handling support in SQL Server 2005. In one of the upcoming blog enteries, we will see how SQL Server 2005 Profiler makes the deadlock analysis easier by presenting the deadlock graph as well as allowing us to save the results in the form of XML.

About these ads

2 Responses to “Interpreting deadlock trace output in SQL Server”

  1. [...] Posted by decipherinfosys on January 25th, 2007 In one of the previous posts : http://decipherinfosys.wordpress.com/2007/01/21/interpreting-deadlock-trace-output-in-sql-server/ [...]

  2. [...] can be used to handle deadlocks as well. We had covered that in one of our previous blog post here. • RAISERROR can also be used within either the TRY or the CATCH block. If the error severity is [...]

Sorry, the comment form is closed at this time.

 
Follow

Get every new post delivered to your Inbox.

Join 74 other followers

%d bloggers like this: