Need Help Troubleshooting Sql Server 2005 Deadlock Scenario

dba.stackexchange https://dba.stackexchange.com/questions/8351

Question

I am running into a deadlock scenario where the only participants in the deadlock appear to be a single table and a single stored procedure that deletes from that table. I drew that conclusion based on my analysis of the sql error log at the time of several of these deadlocks, using the MSDN article below as a guideline to decipher the trace in the error log.

The table DEXTable and the stored procedure ClearDEXTableRows are defined below. There is another stored procedure InsertDEXTableRow that inserts rows into DEXTable, but that proc does not seem to be involved in the deadlock based on the entries in the sql error log.

The DEXTable has ~8.3 million rows in it, and tends to grow steadily. The Respondent table is also large and tends to grow steadily.

It is accessed from a high traffic volume website with pages that frequently call ClearDEXTableRows and InsertDEXTableRow in quick succession.

The deadlock has occurred between 0 and 9 times per day for the past 10 days.

I've enabled sql trace for 1222 (using DBCC TRACEON 1222) and just recently enabled flag 1204. There's a good description of the output for these flags on Detecting and Ending Deadlocks

My questions are:

Does it make sense that only this one stored procedure ClearDEXTableRows is the cause of the deadlock?

If so, can anyone offer a good explanation of how this can happen and recommend a way to fix it?
My suspicion is that the DELETE statements are causing contention on the PK for DEXTable which needs to be rebuilt frequently.

If not, what additional trace should I enable to dig deeper into the cause of the deadlock? (I do want to learn here)

-- Table definition
CREATE TABLE [dbo].[DEXTable](
                [ExportID] [int] NOT NULL,
                [RespondentID] [int] NOT NULL,
                [Exported] [datetime] NOT NULL,
CONSTRAINT [PK_DEXTable] PRIMARY KEY CLUSTERED
(
                [ExportID] ASC,
                [RespondentID] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
) ON [PRIMARY]

GO

ALTER TABLE [dbo].[DEXTable]  WITH CHECK ADD  CONSTRAINT [FK_DEXTable_Exports] FOREIGN KEY([ExportID])
REFERENCES [dbo].[Exports] ([ExportID])
ON DELETE CASCADE
GO

ALTER TABLE [dbo].[DEXTable] CHECK CONSTRAINT [FK_DEXTable_Exports]
GO

ALTER TABLE [dbo].[DEXTable]  WITH CHECK ADD  CONSTRAINT [FK_DEXTable_Respondents] FOREIGN KEY([RespondentID])
REFERENCES [dbo].[Respondents] ([RespondentID])
GO

ALTER TABLE [dbo].[DEXTable] CHECK CONSTRAINT [FK_DEXTable_Respondents]
GO

ALTER TABLE [dbo].[DEXTable] ADD  DEFAULT (getdate()) FOR [Exported]
GO

-- "ClearDEXTableRows"
-- Clear a respondent's export records to trigger re-export.
CREATE PROCEDURE [dbo].[ClearDEXTableRows]
    @RespondentID int
AS
    DELETE DEXTable WITH (ROWLOCK)
    WHERE RespondentID = @RespondentID
GO

-- "InsertDEXTableRow"
-- Insert record noting export run for a particular respondent.
CREATE PROCEDURE [dbo].[InsertDEXTableRow]
    @ExportID int,
    @RespondentID int
AS
    IF NOT EXISTS (SELECT RespondentID FROM DEXTable WHERE ExportID = @ExportID AND RespondentID = @RespondentID)
    BEGIN
      INSERT DEXTable
        (ExportID, RespondentID, Exported)
      VALUES
        (@ExportID, @RespondentID, getdate())
    END
    ELSE
    BEGIN
      UPDATE DEXTable
      SET Exported = getdate()
      WHERE ExportID = @ExportID AND RespondentID = @RespondentID
    END
GO

And here are some of the log entries (I'm not entirely sure what's helpful)

-- Sql error log for one of the recent deadlocks
-- Most recent entries in the log are at the top and go further back in time as you read down

11/17/2011 00:00:58,spid18s,Unknown,This instance of SQL Server has been using a process ID of 1840 since 10/31/2011 7:19:43 PM (local) 11/1/2011 12:19:43 AM (UTC). This is an informational message only; no user action is required.

11/16/2011 20:37:59,spid20s,Unknown,waiter id=process86a6478 mode=U requestType=wait

11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processac352e9b8 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lockd32579f80 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=process47eda8 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processac352e9b8 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lockc48e52780 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=processce50ce088 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processac352e9b8 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=locka6ad4e580 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=process8691198 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processcd7b1b048 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lock95f600780 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=process478da8 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processcd7b1b048 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lock955c98200 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=process700328 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processcd7b1b048 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lock83fd3b200 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=processffaef8 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processac352e9b8 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lock77b633580 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=process86a6ef8 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processcd7b1b048 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lockdc536d580 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter event=e_waitPipeGetRow type=consumer id=processcd7b1b048
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process717198
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=processffaef8
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process86a6478
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=processdc28aeef8
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=processce50ce088
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process47eda8
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,exchangeEvent id=port80314690 nodeId=3
11/16/2011 20:37:59,spid20s,Unknown,waiter id=process717198 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processac352e9b8 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lock68f374980 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=process716c58 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processcd7b1b048 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lock60e8d8a80 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=process47f198 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processdc28aeef8 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lockb7c7f1c00 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter id=processdc28aeef8 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processac352e9b8 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lock7797b6500 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,waiter event=e_waitPipeGetRow type=consumer id=processac352e9b8
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process6d5c18
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process716c58
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process478da8
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process8691198
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process86a6ef8
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process700328
11/16/2011 20:37:59,spid20s,Unknown,owner event=e_waitNone type=producer id=process47f198
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,exchangeEvent id=port80315870 nodeId=3
11/16/2011 20:37:59,spid20s,Unknown,waiter id=process6d5c18 mode=U requestType=wait
11/16/2011 20:37:59,spid20s,Unknown,waiter-list
11/16/2011 20:37:59,spid20s,Unknown,owner id=processcd7b1b048 mode=U
11/16/2011 20:37:59,spid20s,Unknown,owner-list
11/16/2011 20:37:59,spid20s,Unknown,keylock hobtid=72057594060931072 dbid=5 objectname=MyServer_Database.dbo.DEXTable indexname=PK_DEXTable id=lock46a62fe00 mode=U associatedObjectId=72057594060931072
11/16/2011 20:37:59,spid20s,Unknown,resource-list
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=processdc28aeef8 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (d600a7d4a467) waittime=4836 ownerId=299785428 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.820 XDES=0xce4278410 lockMode=U schedulerid=8 kpid=15756 status=suspended spid=157 sbid=0 ecid=6 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.820 lastbatchcompleted=2011-11-16T20:37:53.807 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785428 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=processce50ce088 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (d1007416f809) waittime=5538 ownerId=299785428 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.820 XDES=0x946b46d30 lockMode=U schedulerid=4 kpid=20396 status=suspended spid=157 sbid=0 ecid=3 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.820 lastbatchcompleted=2011-11-16T20:37:53.807 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785428 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,Proc [Database Id = 5 Object Id = 957962489]
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=processcd7b1b048 taskpriority=0 logused=20003 waittime=4118 schedulerid=3 kpid=13252 status=suspended spid=157 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2011-11-16T20:37:53.820 lastbatchcompleted=2011-11-16T20:37:53.807 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 loginname=IIS APPPOOL\MyServer_Database isolationlevel=read committed (2) xactid=299785428 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,Proc [Database Id = 5 Object Id = 957962489]
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=processac352e9b8 taskpriority=0 logused=20003 waittime=4071 schedulerid=10 kpid=20384 status=suspended spid=147 sbid=0 ecid=0 priority=0 transcount=2 lastbatchstarted=2011-11-16T20:37:53.823 lastbatchcompleted=2011-11-16T20:37:53.810 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 loginname=IIS APPPOOL\MyServer_Database isolationlevel=read committed (2) xactid=299785445 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process86a6ef8 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (ab0001e10f4e) waittime=6099 ownerId=299785445 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.823 XDES=0xdb9b53cc0 lockMode=U schedulerid=11 kpid=17448 status=suspended spid=147 sbid=0 ecid=4 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.823 lastbatchcompleted=2011-11-16T20:37:53.810 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785445 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process86a6478 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (7500c3691103) waittime=6099 ownerId=299785428 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.820 XDES=0xdb9b53a80 lockMode=U schedulerid=11 kpid=19324 status=suspended spid=157 sbid=0 ecid=7 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.820 lastbatchcompleted=2011-11-16T20:37:53.807 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785428 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process8691198 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (d20082032104) waittime=6052 ownerId=299785445 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.823 XDES=0xabdc20870 lockMode=U schedulerid=10 kpid=24760 status=suspended spid=147 sbid=0 ecid=7 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.823 lastbatchcompleted=2011-11-16T20:37:53.810 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785445 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=processffaef8 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (f900d9903a2a) waittime=6099 ownerId=299785428 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.820 XDES=0xd9f26e080 lockMode=U schedulerid=9 kpid=16712 status=suspended spid=157 sbid=0 ecid=8 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.820 lastbatchcompleted=2011-11-16T20:37:53.807 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785428 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process717198 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (4700497f7879) waittime=5959 ownerId=299785428 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.820 XDES=0x8006dcc0 lockMode=U schedulerid=6 kpid=7420 status=suspended spid=157 sbid=0 ecid=12 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.820 lastbatchcompleted=2011-11-16T20:37:53.807 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785428 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process716c58 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (5a00f098709d) waittime=5928 ownerId=299785445 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.823 XDES=0x6c020d880 lockMode=U schedulerid=6 kpid=17856 status=suspended spid=147 sbid=0 ecid=11 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.823 lastbatchcompleted=2011-11-16T20:37:53.810 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785445 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process700328 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (51003376bf57) waittime=6099 ownerId=299785445 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.823 XDES=0x92beba3d0 lockMode=U schedulerid=5 kpid=7004 status=suspended spid=147 sbid=0 ecid=3 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.823 lastbatchcompleted=2011-11-16T20:37:53.810 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785445 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process6d5c18 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (150048fb6c35) waittime=5803 ownerId=299785445 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.823 XDES=0xdbadb2560 lockMode=U schedulerid=3 kpid=3824 status=suspended spid=147 sbid=0 ecid=12 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.823 lastbatchcompleted=2011-11-16T20:37:53.810 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785445 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process47f198 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (4700c2a10b35) waittime=6037 ownerId=299785445 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.823 XDES=0x6c2da4080 lockMode=U schedulerid=2 kpid=8564 status=suspended spid=147 sbid=0 ecid=1 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.823 lastbatchcompleted=2011-11-16T20:37:53.810 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785445 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process47eda8 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (2a004ee465b9) waittime=6099 ownerId=299785428 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.820 XDES=0x6c2da4870 lockMode=U schedulerid=2 kpid=24652 status=suspended spid=157 sbid=0 ecid=1 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.820 lastbatchcompleted=2011-11-16T20:37:53.807 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785428 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,inputbuf
11/16/2011 20:37:59,spid20s,Unknown,WHERE RespondentID = @RespondentID
11/16/2011 20:37:59,spid20s,Unknown,DELETE DEXTable WITH (ROWLOCK)
11/16/2011 20:37:59,spid20s,Unknown,frame procname=MyServer_Database.dbo.ClearDEXTableRows line=7 stmtstart=334 sqlhandle=0x03000500f958193991f66b01a29e00000100000000000000
11/16/2011 20:37:59,spid20s,Unknown,executionStack
11/16/2011 20:37:59,spid20s,Unknown,process id=process478da8 taskpriority=0 logused=0 waitresource=KEY: 5:72057594060931072 (1400c876e809) waittime=5709 ownerId=299785445 transactionname=DELETE lasttranstarted=2011-11-16T20:37:53.823 XDES=0x857272d30 lockMode=U schedulerid=1 kpid=7804 status=suspended spid=147 sbid=0 ecid=9 priority=0 transcount=0 lastbatchstarted=2011-11-16T20:37:53.823 lastbatchcompleted=2011-11-16T20:37:53.810 clientapp=.Net SqlClient Data Provider hostname=309389-DB13 hostpid=6536 isolationlevel=read committed (2) xactid=299785445 currentdb=5 lockTimeout=4294967295 clientoption1=671088672 clientoption2=128056
11/16/2011 20:37:59,spid20s,Unknown,process-list
11/16/2011 20:37:59,spid20s,Unknown,deadlock victim=processdc28aeef8
11/16/2011 20:37:59,spid20s,Unknown,deadlock-list
11/16/2011 16:40:12,spid83,Unknown,DBCC TRACEON 1222<c/> server process ID (SPID) 83. This is an informational message only; no user action is required.
Was it helpful?

Solution

Three things leap out:

  1. Your DELETE is on the 2nd column (RespondentID) of the current PK which means a scan, not a seek.

  2. Pointless ROWLOCK hint

  3. Your "UPSERT" pattern is not concurrency safe. The test for existence may pass for 2 overlapping (in time) concurrent threads giving an error.

To fix

  1. Reverse your PK order in DEXTable to (RespondentID, ExportID). Or add a separate index on RespondentID alone. Personally, I'd probably reverse the PK order.

  2. Remove ROWLOCK hint. If it continues after index and UPSERT changes suggested here, try UPDLOCK, but only after checking for parallelism

  3. Check for parallelism in the plan: try MAXDOP 1 to restrict. Try this before UPDLOCK

  4. Use the "JFDI" UPSERT pattern. That is, the INSERT will check uniqueness anyway so just INSERT, if it fails then UPDATE.

For SQL Server 2005 (you'd use MERGE on SQL Server 2008+)

BEGIN TRY

    BEGIN TRY
        INSERT DEXTable (ExportID, RespondentID, Exported)
        VALUES (@ExportID, @RespondentID, getdate())
    END TRY
    BEGIN CATCH
        IF ERROR_NUMBER() = 2627
            UPDATE DEXTable
            SET Exported = getdate()
            WHERE ExportID = @ExportID AND RespondentID = @RespondentID
        ELSE
        BEGIN
           ..process real error
           RAISERROR (...)
        END
    END CATCH

END TRY
BEGIN CATCH
    ..process
    RAISERROR (...)
END CATCH

Finally, MSDN recommends that you trap deadlock errors and re-try on the client side. This should part of your data access layer that handles all your SQL calls.

OTHER TIPS

+1 for @gbn's explanation of the likely cause but I'm not a fan of the suggested INSERT/UPDATE pattern, unless an update is truly the exceptional case (i.e. 99.99% of the time an insert occurs). My preferred approach has always been:

BEGIN TRANSACTION

UPDATE DEXTable WITH (UPDLOCK, HOLDLOCK)
SET Exported = getdate()
WHERE ExportID = @ExportID AND RespondentID = @RespondentID

IF (@@ROWCOUNT = 0)
BEGIN
    INSERT DEXTable (ExportID, RespondentID, Exported)
    VALUES (@ExportID, @RespondentID, getdate())
END

COMMIT TRANSACTION

You could also alleviate the deadlock with by adding hints to your current query:

BEGIN TRANSACTION

IF NOT EXISTS (SELECT RespondentID FROM DEXTable WITH (UPDLOCK, HOLDLOCK) WHERE ExportID = @ExportID AND RespondentID = @RespondentID)
    BEGIN
      INSERT DEXTable
        (ExportID, RespondentID, Exported)
      VALUES
        (@ExportID, @RespondentID, getdate())
    END
    ELSE
    BEGIN
      UPDATE DEXTable
      SET Exported = getdate()
      WHERE ExportID = @ExportID AND RespondentID = @RespondentID
    END

COMMIT TRANSACTION

Without more deadlock info I'm just guessing here but...

There's no index on the column that you are using find the rows to delete. This means a clustered index scan each time which means lots of locks when the delete starts. Even though you've got WITH (ROWLOCK) in there there still needs to be schema locks on the table to make sure that nothing is going on.

Try adding an index on the RespondentID column and see if that fixes the problem. Looking at the execution plan before and after that index are created should give some indication as to the problem being fixed as well.

Licensed under: CC-BY-SA with attribution
Not affiliated with dba.stackexchange
scroll top