Transaction (Process ID 128) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
The issue was two transactions were trying to do select on a shared resource (table), while they each were holding exclusive lock on the same table index because of previous insert statement issued on the same table in each transaction.
Let me first go over how do you identify which resources are deadlocking. In Sql Server 2005, (thats the one I was using) there are two ways to do it.
(1) Use SQL Server Profiler. SQL Server Profiler is a graphical tool which helps you capture deadlock trace.More info can be obtained if you look at msdn documentation.
(2) Second option is to enable flag 1222 with “DBCC TRACEON (1222, -1)” or by adding “-T1222” as a SQL startup parameter. This will log trace information on sql server log. More information on this can be obtained here.
A trace with DBCC flag 1222 looks like below:
08/04/2010 11:58:44,spid4s,Unknown,Deadlock encountered .... Printing deadlock information
08/04/2010 11:58:38,spid14s,Unknown,waiter id=processaa8d48 mode=S requestType=wait
08/04/2010 11:58:38,spid14s,Unknown,waiter-list
08/04/2010 11:58:38,spid14s,Unknown,owner id=processa1bc48 mode=X
08/04/2010 11:58:38,spid14s,Unknown,owner-list
08/04/2010 11:58:38,spid14s,Unknown,keylock hobtid=72057594058113024 dbid=6 objectname=OrderDB_Debug.dbo.CustomerInstances indexname=PK_CustomerInstances id=lock59481a00 mode=X associatedObjectId=72057594058113024
08/04/2010 11:58:38,spid14s,Unknown,waiter id=processa1bc48 mode=S requestType=wait
08/04/2010 11:58:38,spid14s,Unknown,waiter-list
08/04/2010 11:58:38,spid14s,Unknown,owner id=processaa8d48 mode=X
08/04/2010 11:58:38,spid14s,Unknown,owner-list
08/04/2010 11:58:38,spid14s,Unknown,keylock hobtid=72057594058113024 dbid=6 objectname=OrderDB_Debug.dbo.CustomerInstances indexname=PK_CustomerInstances id=lock3b8a2500 mode=X associatedObjectId=72057594058113024
08/04/2010 11:58:38,spid14s,Unknown,resource-list
08/04/2010 11:58:38,spid14s,Unknown,set implicit_transactions on
08/04/2010 11:58:38,spid14s,Unknown,inputbuf
08/04/2010 11:58:38,spid14s,Unknown,unknown
08/04/2010 11:58:38,spid14s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
08/04/2010 11:58:38,spid14s,Unknown,select orderentry0.order_entry_id as order1_11 orderentry0.audit_creation_timestamp as audit2_11_ orderentry0.audit_creation_user as audit3_11_ orderentry0.audit_updated_timestamp as audit4_11_ orderentry0.audit_updated_user as audit5_11_ orderentry0.customer_instance_id as customer_instance9_11 orderentry0.line_item_id as line_item10_11 orderentry0.is_deleted as is6_11_ orderentry0.is_expired as is7_11_ orderentry0.expiration_timestamp as expiration8_11_ from Orders orderentry0 CustomerInstances customer1_ where orderentry0.customer_instance_id=customer1_.customer_instance_id and customer1_.customer_instance_guid=@P0 and orderentry0.is_deleted=0
08/04/2010 11:58:38,spid14s,Unknown,frame procname=adhoc line=1 stmtstart=40 sqlhandle=0x0200000085a17c084fc7a9b5a8d6545805f76b6d8b65d45e
08/04/2010 11:58:38,spid14s,Unknown,executionStack
08/04/2010 11:58:38,spid14s,Unknown,process id=processaa8d48 taskpriority=0 logused=5724 waitresource=KEY: 6:72057594058113024 (09005c5740ca) waittime=3062 ownerId=1120537422 transactionname=implicit_transaction lasttranstarted=2010-08-04T11:58:35.153 XDES=0x586cb450 lockMode=S schedulerid=2 kpid=8100 status=suspended spid=130 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2010-08-04T11:58:35.513 lastbatchcompleted=2010-08-04T11:58:35.497 clientapp=Microsoft SQL Server JDBC Driver hostname=testpc-wxp hostpid=0 loginname=OrderDBApp isolationlevel=read committed (2) xactid=1120537422 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128058
08/04/2010 11:58:38,spid14s,Unknown,set implicit_transactions on
08/04/2010 11:58:38,spid14s,Unknown,inputbuf
08/04/2010 11:58:38,spid14s,Unknown,unknown
08/04/2010 11:58:38,spid14s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
08/04/2010 11:58:38,spid14s,Unknown,select customer0_.customer_instance_id as customer_instance1_5_ customer0_.audit_creation_timestamp as audit2_5_ customer0_.audit_creation_user as audit3_5_ customer0_.audit_updated_timestamp as audit4_5_ customer0_.audit_updated_user as audit5_5_ customer0_.customer_instance_creation_timestamp as timestamp6_5_ customer0_.address_id as address15_5_ customer0_.is_deleted as is7_5_ customer0_.description as descript8_5_ customer0_.stop_offset as stop9_5_ customer0_.is_expired as is10_5_ customer0_.expiration_timestamp as expiration11_5_ customer0_.customer_instance_guid as guid12_5_5 customer0_.account_domain_id as account16_5_ customer0_.start_offset as start13_5_ customer0_.customer_instance_title as title14_5_ from CustomerInstances customer0_ where customer0_.customer_instance_guid=@P0 and customer0_.is_deleted=0
08/04/2010 11:58:38,spid14s,Unknown,frame procname=adhoc line=1 stmtstart=40 sqlhandle=0x02000000ccb2262052f4ec84e1255595ca29f072773c6739
08/04/2010 11:58:38,spid14s,Unknown,executionStack
08/04/2010 11:58:38,spid14s,Unknown,process id=processa1bc48 taskpriority=0 logused=6160 waitresource=KEY: 6:72057594058113024 (0a00b2f8f5d8) waittime=2906 ownerId=1120537421 transactionname=implicit_transaction lasttranstarted=2010-08-04T11:58:34.950 XDES=0x21dc8958 lockMode=S schedulerid=1 kpid=6888 status=suspended spid=123 sbid=0 ecid=0 priority=0 transcount=1 lastbatchstarted=2010-08-04T11:58:35.670 lastbatchcompleted=2010-08-04T11:58:35.653 clientapp=Microsoft SQL Server JDBC Driver hostname=radval-wxp hostpid=0 loginname=OrderDBApp isolationlevel=read committed (2) xactid=1120537421 currentdb=6 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128058
08/04/2010 11:58:38,spid14s,Unknown,process-list
08/04/2010 11:58:38,spid14s,Unknown,deadlock victim=processaa8d48
08/04/2010 11:58:38,spid14s,Unknown,deadlock-list
08/04/2010 11:58:38,spid4s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x586CB450 Mode: S SPID:130 BatchID:0 ECID:0 TaskProxy:(0x1F74C378) Value:0x358e9820 Cost:(0/5724)
08/04/2010 11:58:38,spid4s,Unknown,Victim Resource Owner:
08/04/2010 11:58:38,spid4s,Unknown,Log Viewer could not read information for this log entry. Cause: Data is Null. This method or property cannot be called on Null values.. Content:
08/04/2010 11:58:38,spid4s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x586CB450 Mode: S SPID:130 BatchID:0 ECID:0 TaskProxy:(0x1F74C378) Value:0x358e9820 Cost:(0/5724)
08/04/2010 11:58:38,spid4s,Unknown,Requested By:
08/04/2010 11:58:38,spid4s,Unknown,Input Buf: Language Event: set implicit_transactions on
08/04/2010 11:58:38,spid4s,Unknown,SPID: 123 ECID: 0 Statement Type: SELECT Line #: 1
08/04/2010 11:58:38,spid4s,Unknown,Owner:0x54FEB960 Mode: X Flg:0x0 Ref:0 Life:02000000 SPID:123 ECID:0 XactLockInfo: 0x21DC897C
08/04/2010 11:58:38,spid4s,Unknown,Grant List 0:
08/04/2010 11:58:38,spid4s,Unknown,KEY: 6:72057594058113024 (09005c5740ca) CleanCnt:2 Mode:X Flags: 0x0
08/04/2010 11:58:38,spid4s,Unknown,Node:2
08/04/2010 11:58:38,spid4s,Unknown,Log Viewer could not read information for this log entry. Cause: Data is Null. This method or property cannot be called on Null values.. Content:
08/04/2010 11:58:38,spid4s,Unknown,ResType:LockOwner Stype:'OR'Xdes:0x21DC8958 Mode: S SPID:123 BatchID:0 ECID:0 TaskProxy:(0x54D9C378) Value:0x54feb740 Cost:(0/6160)
08/04/2010 11:58:38,spid4s,Unknown,Requested By:
08/04/2010 11:58:38,spid4s,Unknown,Input Buf: Language Event: set implicit_transactions on
08/04/2010 11:58:38,spid4s,Unknown,SPID: 130 ECID: 0 Statement Type: SELECT Line #: 1
08/04/2010 11:58:38,spid4s,Unknown,Owner:0x5C48D120 Mode: X Flg:0x0 Ref:0 Life:02000000 SPID:130 ECID:0 XactLockInfo: 0x586CB474
08/04/2010 11:58:38,spid4s,Unknown,Grant List 1:
08/04/2010 11:58:38,spid4s,Unknown,KEY: 6:72057594058113024 (0a00b2f8f5d8) CleanCnt:3 Mode:X Flags: 0x0
08/04/2010 11:58:38,spid4s,Unknown,Node:1
08/04/2010 11:58:38,spid4s,Unknown,Log Viewer could not read information for this log entry. Cause: Data is Null. This method or property cannot be called on Null values.. Content:
08/04/2010 11:58:38,spid4s,Unknown,Wait-for graph
08/04/2010 11:58:38,spid4s,Unknown,Deadlock encountered .... Printing deadlock information
08/04/2010 11:57:55,spid126,Unknown,DBCC TRACEON 1222 server process ID (SPID) 126. This is an informational message only; no user action is required.
You need to read above trace from bottom to top. What this is telling us is that there two transaction with processid processaa8d48 and processa1bc48 involved in the deadlock. SQL Server chooses process with id processaa8d48 as the deadlock victim, meaning this transaction is rollbacked by SQL Server.
Process processa1bc48 was executing "select customer0_.customer_instance_id ..." and process processaa8d48 was executing "select orderentry0.order_entry_id as order1_11 ..." when the deadlock occurred.
Looking further at owner-list, you will notice one interesting and very confusing information. What this is saying is as follows:
(1) There is an exclusive (X) lock on index PK_CustomerInstances owned by owner process processaa8d48 and process processa1bc48 is waiting on it requesting a shared lock (S).
(2)There is an exclusive (X) lock on index PK_CustomerInstances owned by owner process processa1bc48 and process processaa8d48 is waiting on it requesting a shared lock (S).
So both process are holding an exclusive lock on index PK_CustomerInstances and both are requesting a shared lock on it and so we have a deadlock. Confusing right.. how can both have exclusive lock and requesting shared lock on the same index???
Reproducing deadlock with simple query:
This has to do with how locking and lock escalation works in SQL Server In fact I can reproduce above deadlock very easily with some simple queries:
(1) Create a table called employee with primary key id.
CREATE TABLE [dbo].[employee](
[id] [int] NOT NULL,
[fname] [nchar](50) NOT NULL,
[lname] [nchar](50) NOT NULL,
[created_at] [datetime] NOT NULL,
CONSTRAINT [PK_employee] PRIMARY KEY CLUSTERED
(
[id] ASC
)WITH (IGNORE_DUP_KEY = OFF) ON [PRIMARY]
) ON [PRIMARY]
(2) Open a new sql server client session (call it session1) start a transaction and insert a record without committing it:
BEGIN TRANSACTION
INSERT INTO [employee]([id],[fname],[lname])VALUES(1,'john','smith')
GO
(3) Now open another new sql server client session (call it session2) start a transaction and insert a record without committing it:
BEGIN TRANSACTION
INSERT INTO [employee]([id],[fname],[lname])VALUES(2,'mary','carter')
GO
(4) Now go back to client session1 and do a select *, you will notice that results are pending.
This is due to the fact that session2 is not yet committed and it also hold a lock on the whole
index of employee table.
SELECT * FROM employee
GO
(5) Go back to client session2 and do a select *:
SELECT * FROM employee
GO
Now you will notice that either session1 or session2 will deadlock and other session will show
the results. This has the same issue as I was having with a complex query and for which I did enable tracing as explained earlier. The reason why deadlock is happening is because we are doing "Select *" and it will scan whole table. Since we have inserted rows in two different transactions without committing them, the select statement blocks in each session and one deadlocks.
This same whole index locking is happening with the complex query for which we have enabled tracing.Somehow the select statements are trying to select rows which were inserted in a different transaction which was not yet committed.
So far we have looked at how deadlock trace looks like in SQL Server and how to reproduce it with a simple query. In next blog I will talk about using various approaches to avoid deadlocks.
Promote your blog
No comments:
Post a Comment