Deadlock Analysis – READ Deadlock from SQL ERRORLOG

Leave a comment (0) Go to comments

How to read DEADLOCK Information in SQL Server ERRORLOG ?

In our previous posts, we learned how to trace dead lock information in SQL Server Errorlog. Once the this information is logged inside SQL Server Logs, then how can we use that information for deadlock analysis.

In case you want to build your test scenario for DEADLOCK, then refer my article, DEADLOCK example with SQL Table and Script.

One we enable trace for DEADLOCKS, then on every event of deadlock, a detailed information about deadlock is  being locked in SQL Server ERRORLOG.

In our case, (refer my previous Article)following error message can be seen in SQL Server error log related to deadlock. I am highlighting some of the key information

2012-02-23 22:18:09.12 spid6s      Deadlock encountered …. Printing deadlock information
2012-02-23 22:18:09.12 spid6s      Wait-for graph
2012-02-23 22:18:09.13 spid6s
2012-02-23 22:18:09.13 spid6s      Node:1


2012-02-23 22:18:09.18 spid6s      RID: 2:1:184:7                 CleanCnt:2 Mode:X Flags: 0×3
2012-02-23 22:18:09.18 spid6s       Grant List 0:
2012-02-23 22:18:09.18 spid6s         Owner:0x000000008017CE40 Mode: X        Flg:0×40 Ref:0 Life:02000000 SPID:57 ECID:0 XactLockInfo: 0x0000000084E79440
2012-02-23 22:18:09.19 spid6s         SPID: 57 ECID: 0 Statement Type: UPDATE Line #: 6
2012-02-23 22:18:09.19 spid6s         Input Buf: Language Event:
– Step 3 update Sales Person Table and update the Sales Region for SalesPersonID 4
– Session 1 (Query Window 1) — Statement 3

BEGIN TRAN
update SalesPerson set Region=’Beijing’ where SalesPersonID = 4;

2012-02-23 22:18:09.19 spid6s      Requested by:
2012-02-23 22:18:09.19 spid6s        ResType:LockOwner Stype:’OR’Xdes:0x0000000084E5F950 Mode: U SPID:53 BatchID:0 ECID:0 TaskProxy:(0x0000000084EC2540) Value:0x85005c80 Cost:(0/120)
2012-02-23 22:18:09.19 spid6s
2012-02-23 22:18:09.19 spid6s     Node:2

2012-02-23 22:18:09.19 spid6s      RID: 2:1:157:3                 CleanCnt:2 Mode:X Flags: 0×3
2012-02-23 22:18:09.19 spid6s       Grant List 0:
2012-02-23 22:18:09.19 spid6s         Owner:0x000000008017BF40 Mode: X        Flg:0×40 Ref:0 Life:02000000 SPID:53 ECID:0 XactLockInfo: 0x0000000084E5F990
2012-02-23 22:18:09.19 spid6s        SPID: 53 ECID: 0 Statement Type: UPDATE Line #: 6
2012-02-23 22:18:09.19 spid6s         Input Buf: Language Event:
– Step 4 update Orders Table and update the Sales OrderDate for Order 108
– Session 2 (Query Window 2) — Statement 4

BEGIN TRAN
update Orders set OrderDate=’2011-11-11 11:11:11.000′ where OrderID = 108;
2012-02-23 22:18:09.19 spid6s      Requested by:
2012-02-23 22:18:09.19 spid6s        ResType:LockOwner Stype:’OR’Xdes:0x0000000084E79400 Mode: U SPID:57 BatchID:0 ECID:0 TaskProxy:(0x0000000084DC2540) Value:0x8017bec0 Cost:(0/196)
2012-02-23 22:18:09.34 spid6s
2012-02-23 22:18:09.34 spid6s      Victim Resource Owner:
2012-02-23 22:18:09.34 spid6s       ResType:LockOwner Stype:’OR’Xdes:0x0000000084E5F950 Mode: U SPID:53 BatchID:0 ECID:0 TaskProxy:(0x0000000084EC2540) Value:0x85005c80 Cost:(0/120)
2012-02-23 22:18:09.36 spid23s     deadlock-list
2012-02-23 22:18:09.36 spid23s      deadlock victim=process4d3048
2012-02-23 22:18:09.36 spid23s       process-list
2012-02-23 22:18:09.37 spid23s       process id=process4d3048 taskpriority=0 logused=120 waitresource=RID: 2:1:184:7 waittime=459 ownerId=356117 transactionname=user_transaction lasttranstarted=2012-02-23T22:17:56.510 XDES=0x84e5f950 lockMode=U schedulerid=3 kpid=10368 status=suspended spid=53 sbid=0 ecid=0 priority=0 trancount=3 lastbatchstarted=2012-02-23T22:18:08.860 lastbatchcompleted=2012-02-23T22:17:56.590 clientapp=Microsoft SQL Server Management Studio – Query hostname=DBATAG  hostpid=968 loginname=DBATAG isolationlevel=read committed (2) xactid=356117 currentdb=2 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2012-02-23 22:18:09.37 spid23s         executionStack
2012-02-23 22:18:09.37 spid23s          frame procname=adhoc line=6 stmtstart=58 sqlhandle=0x02000000e49d262c4e7a570ab8a24babad5eb2842e2e869c
2012-02-23 22:18:09.37 spid23s     UPDATE [Orders] set [OrderDate] = @1  WHERE [OrderID]=@2
2012-02-23 22:18:09.37 spid23s          frame procname=adhoc line=6 stmtstart=276 sqlhandle=0x0200000022f3a72386c7e56f1e90e8cd21461721a3e0a67a
2012-02-23 22:18:09.37 spid23s     update Orders set OrderDate=’2011-11-11 11:11:11.000′ where OrderID = 108;
2012-02-23 22:18:09.37 spid23s         inputbuf
2012-02-23 22:18:09.37 spid23s     — Step 4 update Orders Table and update the Sales OrderDate for Order 108
2012-02-23 22:18:09.37 spid23s     — Session 2 (Query Window 2) — Statement 4
2012-02-23 22:18:09.37 spid23s     BEGIN TRAN
2012-02-23 22:18:09.37 spid23s     update Orders set OrderDate=’2011-11-11 11:11:11.000′ where OrderID = 108;
2012-02-23 22:18:09.37 spid23s        process id=process43f048 taskpriority=0 logused=196 waitresource=RID: 2:1:157:3 waittime=7212 ownerId=353074 transactionname=user_transaction lasttranstarted=2012-02-23T22:17:18.967 XDES=0x84e79400 lockMode=U schedulerid=1 kpid=6448 status=suspended spid=57 sbid=0 ecid=0 priority=0 trancount=4 lastbatchstarted=2012-02-23T22:18:02.093 lastbatchcompleted=2012-02-23T22:17:49.167 clientapp=Microsoft SQL Server Management Studio – Query hostname=DBATAG hostpid=968 loginname=DBATAG isolationlevel=read committed (2) xactid=353074 currentdb=2 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2012-02-23 22:18:09.37 spid23s         executionStack
2012-02-23 22:18:09.37 spid23s          frame procname=adhoc line=6 stmtstart=58 sqlhandle=0x020000005d7ef62e1c25a6069814688d37c8893e368f37ac
2012-02-23 22:18:09.37 spid23s     UPDATE [SalesPerson] set [Region] = @1  WHERE [SalesPersonID]=@2
2012-02-23 22:18:09.37 spid23s          frame procname=adhoc line=6 stmtstart=294 sqlhandle=0x02000000b9aa5a33ee4c7af1c2eeb2cd8572c35f2638e203
2012-02-23 22:18:09.37 spid23s     update SalesPerson set Region=’Beijing’ where SalesPersonID = 4;
2012-02-23 22:18:09.37 spid23s         inputbuf
2012-02-23 22:18:09.37 spid23s     — Step 3 update Sales Person Table and update the Sales Region for SalesPersonID 4
2012-02-23 22:18:09.37 spid23s     — Session 1 (Query Window 1) — Statement 3
2012-02-23 22:18:09.37 spid23s     BEGIN TRAN
2012-02-23 22:18:09.37 spid23s     update SalesPerson set Region=’Beijing’ where SalesPersonID = 4;
2012-02-23 22:18:09.37 spid23s       resource-list
2012-02-23 22:18:09.37 spid23s        ridlock fileid=1 pageid=184 dbid=2 objectname=tempdb.dbo.Orders id=lock8012e600 mode=X associatedObjectId=1224979099300986880
2012-02-23 22:18:09.37 spid23s         owner-list
2012-02-23 22:18:09.37 spid23s          owner id=process43f048 mode=X
2012-02-23 22:18:09.37 spid23s         waiter-list
2012-02-23 22:18:09.37 spid23s          waiter id=process4d3048 mode=U requestType=wait
2012-02-23 22:18:09.37 spid23s       ridlock fileid=1 pageid=157 dbid=2 objectname=tempdb.dbo.SalesPerson id=lock826ba480 mode=X associatedObjectId=1297036693379874816
2012-02-23 22:18:09.37 spid23s         owner-list
2012-02-23 22:18:09.37 spid23s          owner id=process4d3048 mode=X
2012-02-23 22:18:09.37 spid23s         waiter-list
2012-02-23 22:18:09.37 spid23s          waiter id=process43f048 mode=U requestType=wait

 

Interpretation from above mentioned Error Information

  • SPID 53 is running an update statement “UPDATE [Orders] set [OrderDate] = @1  WHERE [OrderID]=@2″.  It holds an U lock on ridlock fileid=1 pageid=184 dbid=2 objectname=tempdb.dbo.Orders id=lock8012e600 mode=X associatedObjectId=1224979099300986880.  This lock is blocking SPID 57, which is waiting to acquire an X lock on that key resource.
  • SQL Server has chosen SPID 53 as the deadlock victim, it’s batch will cancelled and it’s transaction will be rolled back.

To make you more clear, graphically, I enabled the profiler and capture the Deadlock graph, which given me this information.

Deadlock Analysis   READ Deadlock from SQL ERRORLOG trace sql server deadlock sql server deadlock trace flags deadlock

If I would have enabled the profiler to capture Deadlock Graph then this what I am going to get

This summaries, how can we READ Deadlock from SQL ERRORLOG for Deadlock Analysis.

EOF - Deadlock Analysis – READ Deadlock from SQL ERRORLOG, SQL Server 2012 , 2008 R2 , 2008 , 2005 , 2000

Leave a Reply

Your email address will not be published. Required fields are marked *


*


You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>

Notify me of followup comments via e-mail. You can also subscribe without commenting.