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

Question

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.)

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?

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.

Answer 1

I didn't get a chance to rerun the trace and capture the more nicely formatted XDL file, but in the meantime I was able to resolve the issue by removing all the isolation level and locking hints from the trigger and modifying the application code to run the INSERT itself from within a serializable transaction.

The app uses LINQ to SQL, so the INSERT statement is dynamically generated and run under the default READ COMMITTED isolation level. From the deadlock trace, I could tell that the locks taken by the INSERT were conflicting with the locks taken by the trigger. The deadlock was happening even after removing all the isolation and locking hints from the trigger, so I surmised that the trigger's UPDATE statements were causing stronger locks than the INSERT statement. And when the competing simultaneous transaction tried to do the same thing, the deadlock occurred.

We were definitely on the right track with our previous attempted solutions: using higher isolation levels and stronger locking in the trigger. The problem is that the weaker locks were already taken by the INSERT statement generated by the LINQ to SQL, before the trigger ever got called. The solution is to explicitly start a transaction in our .NET code using SERALIZABLE isolation level, do the insert in that transaction, let the trigger happen in the same transaction (without altering the isolation level or lock hints) and then commit and dispose the transaction. When I did that, I was no longer able to reproduce the issue (I even put it back to the old way and verified that the issue returned.) Here is the new code:

            ' Do the insert in a serializable transaction to prevent simultaneous inserts from deadlocking
            ' due to the trigger, which reaches out to other rows.
            Me.packageContext.Connection.Open()
            Try
                Using oTransaction = Me.packageContext.Connection.BeginTransaction(IsolationLevel.Serializable)
                    Me.packageContext.Transaction = oTransaction
                    Try
                        Me.packageContext.SubmitChanges()
                        oTransaction.Commit()
                    Catch ex As Exception
                        oTransaction.Rollback()
                        Throw
                    End Try
                End Using
            Finally
                ' We need to close the connection and null out the transaction to allow
                ' subsequent uses of the same DataContext to work properly outside this transaction.
                Me.packageContext.Connection.Close()
                Me.packageContext.Transaction = Nothing
            End Try

Normally we avoid opening transactions from within client side code, because they can run long if the code does remote API calls, causing excessive blocking. But in this case we are isolating a very small bit of code, and we have robust error/rollback handling around it.

An alternate solution would be to implement stored procedures that do the INSERTs within explicit SERIALIZABLE transactions, and then alter the DataContext to call the stored procedure. However, that solution is less maintainable as it requires updating both the stored procedure and the DataContext definition every time the schema changes.

Finally, another potential alternate solution would be to examine the deadlock log in detail and find a way to adjust our indexes or keys to avoid the deadlock in the first place. However, that is more difficult and may not be possible with our design.

I think the solution above is the simplest and most understandable for future developers.