Skip to main content
Database Administrators

Return to Question

Clarified title
Source Link
Jordan Rieger
Jordan Rieger
  • 461
  • 1
  • 6
  • 14

Why are these two INSERTs deadlocking (is? Is it the trigger?) What does this deadlock trace 1222 log tell me?

We are seeing intermittent deadlocks in production when receiving multiple simultaneous API requests. Each request basically culminates in an INSERT statement into the same table, which is where we see the deadlock. I wrote a double-threaded console application that can reliably reproduce the issue by simply executing two API requests simultaneously, but only in production, not in staging. (This leads me to believe that there is something about our staging database -- possibly the volume of data, SQL Server version2012 vs 2005, or index tuning -- that differs from production in such a way that the deadlock is avoided. The code is identical, as I believe is the schema.)

Why are these two INSERTs deadlocking (is it the trigger?) What does this deadlock trace 1222 log tell me?

We are seeing intermittent deadlocks in production when receiving multiple simultaneous API requests. Each request basically culminates in an INSERT statement into the same table, which is where we see the deadlock. I wrote a double-threaded console application that can reliably reproduce the issue by simply executing two API requests simultaneously, but only in production, not in staging. (This leads me to believe that there is something about our staging database -- possibly the volume of data, SQL Server version, or index tuning -- that differs from production.)

Why are these two INSERTs deadlocking? Is it the trigger? What does this deadlock trace 1222 log tell me?

We are seeing intermittent deadlocks in production when receiving multiple simultaneous API requests. Each request basically culminates in an INSERT statement into the same table, which is where we see the deadlock. I wrote a double-threaded console application that can reliably reproduce the issue by simply executing two API requests simultaneously, but only in production, not in staging. (This leads me to believe that there is something about our staging database -- possibly the volume of data, SQL Server 2012 vs 2005, or index tuning -- that differs from production in such a way that the deadlock is avoided. The code is identical, as I believe is the schema.)

added 48 characters in body
Source Link
Jordan Rieger
Jordan Rieger
  • 461
  • 1
  • 6
  • 14

Something elseOther info that might help you help me: The table DomainTransferRANT is heavily indexed. Its primary key is a non-clustered GUID. There is a clustered index on another important INT column. And there are 7 other non-clustered indexes. Finally, there are several foreign key constraints.

Something else that might help you help me: The table DomainTransferRANT is heavily indexed. Its primary key is a non-clustered GUID. There is a clustered index on another important INT column. And there are 7 other non-clustered indexes.

Other info that might help you help me: The table DomainTransferRANT is heavily indexed. Its primary key is a non-clustered GUID. There is a clustered index on another important INT column. And there are 7 other non-clustered indexes. Finally, there are several foreign key constraints.

Source Link
Jordan Rieger
Jordan Rieger
  • 461
  • 1
  • 6
  • 14

Why are these two INSERTs deadlocking (is it the trigger?) What does this deadlock trace 1222 log tell me?

We are seeing intermittent deadlocks in production when receiving multiple simultaneous API requests. Each request basically culminates in an INSERT statement into the same table, which is where we see the deadlock. I wrote a double-threaded console application that can reliably reproduce the issue by simply executing two API requests simultaneously, but only in production, not in staging. (This leads me to believe that there is something about our staging database -- possibly the volume of data, SQL Server version, or index tuning -- that differs from production.)

Since I can now reproduce the deadlock, I was able to convince my boss to enable trace flag 1222 temporarily, and captured the log below:

Date,Source,Severity,Message
09/05/2013 16:32:19,spid71,Unknown,DBCC TRACEOFF 1222<c/> server process ID (SPID) 71. This is an informational message only; no user action is required.
09/05/2013 16:30:55,spid17s,Unknown,waiter id=processf34868 mode=X requestType=wait
09/05/2013 16:30:55,spid17s,Unknown,waiter-list
09/05/2013 16:30:55,spid17s,Unknown,owner id=processf35c18 mode=X
09/05/2013 16:30:55,spid17s,Unknown,owner-list
09/05/2013 16:30:55,spid17s,Unknown,objectlock lockPartition=0 objid=428945000 subresource=FULL dbid=8 objectname=MyDB.DomainTransferRAR id=lock120a72c80 mode=X associatedObjectId=428945000
09/05/2013 16:30:55,spid17s,Unknown,waiter id=processf35c18 mode=X requestType=convert
09/05/2013 16:30:55,spid17s,Unknown,waiter-list
09/05/2013 16:30:55,spid17s,Unknown,owner id=processf34868 mode=IX
09/05/2013 16:30:55,spid17s,Unknown,owner-list
09/05/2013 16:30:55,spid17s,Unknown,objectlock lockPartition=0 objid=2096426938 subresource=FULL dbid=8 objectname=MyDB.DomainTransferRANT id=lock11de95480 mode=IX associatedObjectId=2096426938
09/05/2013 16:30:55,spid17s,Unknown,resource-list
09/05/2013 16:30:55,spid17s,Unknown,VALUES (@p0<c/>
09/05/2013 16:30:55,spid17s,Unknown,(@p0 uniqueidentifier<c/>@p1 int<c/>@p2 int<c/>@p3 varchar(8000)<c/>@p4 char(5)<c/>@p5 int<c/>@p6 datetime<c/>@p7 datetime<c/>@p8 varchar(8000)<c/>@p9 char(5)<c/>@p10 int<c/>@p11 datetime<c/>@p12 datetime<c/>@p13 varchar(8000)<c/>@p14 int<c/>@p15 xml<c/>@p16 datetime<c/>@p17 datetime<c/>@p18 varchar(8000)<c/>@p19 datetime<c/>@p20 datetime<c/>@p21 varchar(8000)<c/>@p22 bit<c/>@p23 varchar(8000)<c/>@p24 varchar(8000)<c/>@p25 uniqueidentifier)INSERT INTO [dbo].[DomainTransferRANT]([DomainTransferRANTGUID]<c/> [PrebookedBillPackageId]<c/> [domainID]<c/> [DomainName]<c/> [GainingWNAccountID]<c/> [GainingRegistrantID]<c/> [dtGainingRequestSent]<c/> [dtGainingResponseReceived]<c/> [DomainTransferGainingPartyRespCode]<c/> [LosingWNAccountID]<c/> [LosingRegistrantID]<c/> [dtLosingRequestSent]<c/> [dtLosingResponseReceived]<c/> [DomainTransferLosingPartyRespCode]<c/> [SubmittedBillPackageId]<c/> [ExtraInfo]<c/> [dtRequestSentToRegistry]<c/> [dtResponseFromRegistry]<c/> [DomainTransferRegistryRespCode]<c/> [dtDeleted]<c/> [dtLastChecked]<c/> [DomainTransferStatusCode]<c/> [SendConfirmationForEachDomain]<c/> [SummaryStatus]<c/> [WHOISBeforeTransfer])
09/05/2013 16:30:55,spid17s,Unknown,inputbuf
09/05/2013 16:30:55,spid17s,Unknown,unknown
09/05/2013 16:30:55,spid17s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
09/05/2013 16:30:55,spid17s,Unknown,VALUES (@p0<c/> @p1<c/> @p2<c/> @p3<c/> @p4<c/> @p5<c/> @p6<c/> @p7<c/> @p8<c/> @p9<c/> @p10<c/> @p11<c/> @p12<c/> @p13<c/> @p14<c/> @p15<c/> @p16<c/> @p17<c/> @p18<c/> @p19<c/> @p20<c/> @p21<c/> @p22<c/> @p23<c/> @p24)
09/05/2013 16:30:55,spid17s,Unknown,INSERT INTO [dbo].[DomainTransferRANT]([DomainTransferRANTGUID]<c/> [PrebookedBillPackageId]<c/> [domainID]<c/> [DomainName]<c/> [GainingWNAccountID]<c/> [GainingRegistrantID]<c/> [dtGainingRequestSent]<c/> [dtGainingResponseReceived]<c/> [DomainTransferGainingPartyRespCode]<c/> [LosingWNAccountID]<c/> [LosingRegistrantID]<c/> [dtLosingRequestSent]<c/> [dtLosingResponseReceived]<c/> [DomainTransferLosingPartyRespCode]<c/> [SubmittedBillPackageId]<c/> [ExtraInfo]<c/> [dtRequestSentToRegistry]<c/> [dtResponseFromRegistry]<c/> [DomainTransferRegistryRespCode]<c/> [dtDeleted]<c/> [dtLastChecked]<c/> [DomainTransferStatusCode]<c/> [SendConfirmationForEachDomain]<c/> [SummaryStatus]<c/> [WHOISBeforeTransfer])
09/05/2013 16:30:55,spid17s,Unknown,frame procname=adhoc line=1 stmtstart=738 stmtend=2322 sqlhandle=0x0200000038d7940c60b76abf51c3cf1bc774fe27ba136260
09/05/2013 16:30:55,spid17s,Unknown,select @iLockDummy = 1 from DomainTransferRANT with (TABLOCKX<c/> HOLDLOCK) OPTION(EXPAND VIEWS)
09/05/2013 16:30:55,spid17s,Unknown,frame procname=MyDB.tri_DomainTransferRANT_InsUpd line=68 stmtstart=10336 stmtend=10544 sqlhandle=0x03000800c8c31e75b259fa002fa200000000000000000000
09/05/2013 16:30:55,spid17s,Unknown,executionStack
09/05/2013 16:30:55,spid17s,Unknown,process id=processf35c18 taskpriority=0 logused=2992 waitresource=OBJECT: 8:2096426938:0  waittime=171 ownerId=26880196297 transactionname=user_transaction lasttranstarted=2013-09-05T16:30:55.710 XDES=0x1c7b18b60 lockMode=X schedulerid=2 kpid=34404 status=suspended spid=69 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2013-09-05T16:30:55.763 lastbatchcompleted=2013-09-05T16:30:55.710 clientapp=.Net SqlClient Data Provider hostname=WEB1 hostpid=13216 loginname=client isolationlevel=serializable (4) xactid=26880196297 currentdb=8 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128056
09/05/2013 16:30:55,spid17s,Unknown,VALUES (@p0<c/>
09/05/2013 16:30:55,spid17s,Unknown,(@p0 uniqueidentifier<c/>@p1 int<c/>@p2 int<c/>@p3 varchar(8000)<c/>@p4 char(5)<c/>@p5 int<c/>@p6 datetime<c/>@p7 datetime<c/>@p8 varchar(8000)<c/>@p9 char(5)<c/>@p10 int<c/>@p11 datetime<c/>@p12 datetime<c/>@p13 varchar(8000)<c/>@p14 int<c/>@p15 xml<c/>@p16 datetime<c/>@p17 datetime<c/>@p18 varchar(8000)<c/>@p19 datetime<c/>@p20 datetime<c/>@p21 varchar(8000)<c/>@p22 bit<c/>@p23 varchar(8000)<c/>@p24 varchar(8000)<c/>@p25 uniqueidentifier)INSERT INTO [dbo].[DomainTransferRANT]([DomainTransferRANTGUID]<c/> [PrebookedBillPackageId]<c/> [domainID]<c/> [DomainName]<c/> [GainingWNAccountID]<c/> [GainingRegistrantID]<c/> [dtGainingRequestSent]<c/> [dtGainingResponseReceived]<c/> [DomainTransferGainingPartyRespCode]<c/> [LosingWNAccountID]<c/> [LosingRegistrantID]<c/> [dtLosingRequestSent]<c/> [dtLosingResponseReceived]<c/> [DomainTransferLosingPartyRespCode]<c/> [SubmittedBillPackageId]<c/> [ExtraInfo]<c/> [dtRequestSentToRegistry]<c/> [dtResponseFromRegistry]<c/> [DomainTransferRegistryRespCode]<c/> [dtDeleted]<c/> [dtLastChecked]<c/> [DomainTransferStatusCode]<c/> [SendConfirmationForEachDomain]<c/> [SummaryStatus]<c/> [WHOISBeforeTransfer])
09/05/2013 16:30:55,spid17s,Unknown,inputbuf
09/05/2013 16:30:55,spid17s,Unknown,unknown
09/05/2013 16:30:55,spid17s,Unknown,frame procname=unknown line=1 sqlhandle=0x000000000000000000000000000000000000000000000000
09/05/2013 16:30:55,spid17s,Unknown,VALUES (@p0<c/> @p1<c/> @p2<c/> @p3<c/> @p4<c/> @p5<c/> @p6<c/> @p7<c/> @p8<c/> @p9<c/> @p10<c/> @p11<c/> @p12<c/> @p13<c/> @p14<c/> @p15<c/> @p16<c/> @p17<c/> @p18<c/> @p19<c/> @p20<c/> @p21<c/> @p22<c/> @p23<c/> @p24)
09/05/2013 16:30:55,spid17s,Unknown,INSERT INTO [dbo].[DomainTransferRANT]([DomainTransferRANTGUID]<c/> [PrebookedBillPackageId]<c/> [domainID]<c/> [DomainName]<c/> [GainingWNAccountID]<c/> [GainingRegistrantID]<c/> [dtGainingRequestSent]<c/> [dtGainingResponseReceived]<c/> [DomainTransferGainingPartyRespCode]<c/> [LosingWNAccountID]<c/> [LosingRegistrantID]<c/> [dtLosingRequestSent]<c/> [dtLosingResponseReceived]<c/> [DomainTransferLosingPartyRespCode]<c/> [SubmittedBillPackageId]<c/> [ExtraInfo]<c/> [dtRequestSentToRegistry]<c/> [dtResponseFromRegistry]<c/> [DomainTransferRegistryRespCode]<c/> [dtDeleted]<c/> [dtLastChecked]<c/> [DomainTransferStatusCode]<c/> [SendConfirmationForEachDomain]<c/> [SummaryStatus]<c/> [WHOISBeforeTransfer])
09/05/2013 16:30:55,spid17s,Unknown,frame procname=adhoc line=1 stmtstart=738 stmtend=2322 sqlhandle=0x0200000038d7940c60b76abf51c3cf1bc774fe27ba136260
09/05/2013 16:30:55,spid17s,Unknown,select @iLockDummy = 1 from DomainTransferRAR with (TABLOCKX<c/> HOLDLOCK) OPTION(EXPAND VIEWS)
09/05/2013 16:30:55,spid17s,Unknown,frame procname=MyDB.tri_DomainTransferRANT_InsUpd line=67 stmtstart=10140 stmtend=10334 sqlhandle=0x03000800c8c31e75b259fa002fa200000000000000000000
09/05/2013 16:30:55,spid17s,Unknown,executionStack
09/05/2013 16:30:55,spid17s,Unknown,process id=processf34868 taskpriority=0 logused=3000 waitresource=OBJECT: 8:428945000:0  waittime=171 ownerId=26880196295 transactionname=user_transaction lasttranstarted=2013-09-05T16:30:55.710 XDES=0x1c7b18370 lockMode=X schedulerid=2 kpid=13932 status=suspended spid=93 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2013-09-05T16:30:55.770 lastbatchcompleted=2013-09-05T16:30:55.710 clientapp=.Net SqlClient Data Provider hostname=MYDB hostpid=13216 loginname=client isolationlevel=serializable (4) xactid=26880196295 currentdb=8 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128056
09/05/2013 16:30:55,spid17s,Unknown,process-list
09/05/2013 16:30:55,spid17s,Unknown,deadlock victim=processf35c18
09/05/2013 16:30:55,spid17s,Unknown,deadlock-list
09/05/2013 16:30:08,spid71,Unknown,DBCC TRACEON 1222<c/> server process ID (SPID) 71. This is an informational message only; no user action is required.

One thing to note is that there is a trigger on the insert into the relevant table. The trigger is necessary to determine a status code for the overall record, which may depend on sibling records in the same table. For a long time we thought the trigger was the cause of the deadlocks, so we added increasingly aggressive locking hints to the trigger, culminating in the current setup where we do a TABLOCKX, HOLDLOCK on the relevant table(s) before the critical section. We figured this would completely prevent the deadlocks, at the expense of some performance, by effectively serializing all inserts. But it seems that is not the case. As I understand it, something else prior to our exclusive table locks must already be holding a shared or update lock. But what?

Something else that might help you help me: The table DomainTransferRANT is heavily indexed. Its primary key is a non-clustered GUID. There is a clustered index on another important INT column. And there are 7 other non-clustered indexes.