THE SQL Server Blog Spot on the Web

Welcome to SQLblog.com - The SQL Server blog spot on the web Sign in | |
in Search

The Rambling DBA: Jonathan Kehayias

The random ramblings and rantings of frazzled SQL Server DBA

Anatomy of a Deadlock - Part Deux

There was a very interesting post on the forums regarding a deadlock that is very similar to the deadlock described in the initial Anatomy of a Deadlock post I made a few months back.  This one is slightly different however because it involves Range locks, Serializable Transaction Isolation Level, and a Heap with a Non-Clustered Index.  I am a visual person when it comes to deadlocks, and to figure it all out I often just draw a diagram on paper, but this one is interesting enough to put into Visio and show.

To keep from reposting the entire post, I am going to stick to the pertinent details only on this blog post.  The post has a heap with a non-clustered index on the primary key:

CREATE TABLE [dbo].[T_IC_AUDIT_LOG](
[APP_ID] [varchar](50) NOT NULL,
[TRANSACTION_ID] [varchar](50) NOT NULL,
[USER_NAME] [nvarchar](256) NOT NULL,
[LOG_FUNCTION] [nvarchar](256) NULL,
[LOG_TIME] [datetime] NOT NULL,
[APP_VERSION] [nvarchar](20) NULL,
CONSTRAINT [C_IC_AUDIT_LOG_PK] PRIMARY KEY NONCLUSTERED
(
[TRANSACTION_ID] 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
SET ANSI_PADDING OFF

Then a stored procedure is used to add records to the table:

CREATE PROCEDURE [dbo].[P_IC_AUDIT_LOG_I]
@p_app_name varchar(256),
@p_transaction_id nvarchar(50),
@p_user_name nvarchar(256),
@p_log_function nvarchar(256),
@p_log_time datetime,
@p_app_version nvarchar(20)
AS

SET NOCOUNT ON
SET XACT_ABORT ON

BEGIN
DECLARE
@v_app_id VARCHAR(50)
DECLARE @v_error INT

EXEC
@v_error = P_IC_APP_GET_ID @p_app_name, @v_app_id OUTPUT
IF
@v_error <> 0 RETURN @v_error

DECLARE @v_count INT
SELECT
@v_count = COUNT(*) FROM T_IC_AUDIT_LOG WHERE TRANSACTION_ID=@p_transaction_id;

IF (@v_count >0 )
BEGIN
RETURN
;
END

INSERT INTO
T_IC_AUDIT_LOG (APP_ID, TRANSACTION_ID, [USER_NAME],
LOG_FUNCTION, LOG_TIME, APP_VERSION)
VALUES (@v_app_id, @p_transaction_id, @p_user_name ,
@p_log_function, @p_log_time, @p_app_version)

END
SET NOCOUNT OFF
SET XACT_ABORT OFF

This is being executed from ADO.NET using a System.Transaction, which is forcing it to run Serializable.  The below picture demonstrates why the Deadlock actually is occuring:

image

The SPID on the right, process998f28, calls the stored procedure and gets a RangeS-S lock on the non-clustered index to do the count(*) against the transaction_id column which defines the non-clustered index for the primary key.  Since this is run in a Serializable transaction, the lock is held for the duration of the stored procedure. When the insert is called on this same SPID, process998f28, an SIX lock is issued against the tables Heap allocation.

This deadlock, like the previous one, is timing based.  While the SIX lock is taken for the insert on SPID process998f28, the second SPID, process90aa78, starts the stored procedure and takes a RangeS-S lock on the non-clustered index.  After this happens the original SPID, , will require a RangeI-N lock to update the non-clustered index with the new row.  This will be blocked by the existing RangeS-S lock on the non-clustered index which is being held by SPID process90aa78 for the duration of its execution.

When SPID process90aa78 finishes the count(*) select, it will then need a SIX lock on the Heap allocation, but it will be blocked by the existing SIX lock which is waiting on the RangeS-S lock to release, and the deadlock occurs.

The Deadlock graph for this is:

<deadlock-list>
<
deadlock victim="process90aa78">
<
process-list>
<
process id="process90aa78" taskpriority="0" logused="0" waitresource="OBJECT: 9:1567500813:0 " waittime="46" ownerId="485513" transactionname="user_transaction" lasttranstarted="2008-11-14T19:31:16.347" XDES="0xd0d2040" lockMode="IX" schedulerid="1" kpid="4784" status="suspended" spid="63" sbid="0" ecid="0" priority="0" transcount="2" lastbatchstarted="2008-11-14T19:31:16.347" lastbatchcompleted="2008-11-14T19:31:16.347" clientapp=".Net SqlClient Data Provider" hostname="NCS-LIFENG" hostpid="2776" loginname="test" isolationlevel="serializable (4)" xactid="485513" currentdb="9" lockTimeout="4294967295" clientoption1="673316896" clientoption2="128056">
<
executionStack>
<
frame procname="xxxxx.dbo.P_IC_AUDIT_LOG_I" line="40" stmtstart="1822" stmtend="2330" sqlhandle="0x03000900b0d65c591167e5001c9a00000100000000000000">
INSERT INTO T_IC_AUDIT_LOG(
APP_ID,
TRANSACTION_ID ,
[USER_NAME] ,
LOG_FUNCTION ,
LOG_TIME ,
APP_VERSION
)
VALUES(
@v_app_id,
@p_transaction_id,
@p_user_name ,
@p_log_function ,
@p_log_time ,
@p_app_version
) </frame>
</
executionStack>
<
inputbuf>
Proc [Database Id = 9 Object Id = 1499256496] </inputbuf>
</
process>
<
process id="process998f28" taskpriority="0" logused="936" waitresource="KEY: 9:72057594137280512 (5702e611629e)" waittime="62" ownerId="485490" transactionname="user_transaction" lasttranstarted="2008-11-14T19:31:16.347" XDES="0xcc9e5e0" lockMode="RangeI-N" schedulerid="2" kpid="2684" status="suspended" spid="60" sbid="0" ecid="0" priority="0" transcount="2" lastbatchstarted="2008-11-14T19:31:16.347" lastbatchcompleted="2008-11-14T19:31:16.347" clientapp=".Net SqlClient Data Provider" hostname="NCS-LIFENG" hostpid="2776" loginname="test" isolationlevel="serializable (4)" xactid="485490" currentdb="9" lockTimeout="4294967295" clientoption1="673316896" clientoption2="128056">
<
executionStack>
<
frame procname="xxxxx.dbo.P_IC_AUDIT_LOG_I" line="40" stmtstart="1822" stmtend="2330" sqlhandle="0x03000900b0d65c591167e5001c9a00000100000000000000">
INSERT INTO T_IC_AUDIT_LOG(
APP_ID,
TRANSACTION_ID ,
[USER_NAME] ,
LOG_FUNCTION ,
LOG_TIME ,
APP_VERSION
)
VALUES(
@v_app_id,
@p_transaction_id,
@p_user_name ,
@p_log_function ,
@p_log_time ,
@p_app_version
) </frame>
</
executionStack>
<
inputbuf>
Proc [Database Id = 9 Object Id = 1499256496] </inputbuf>
</
process>
</
process-list>
<
resource-list>
<
objectlock lockPartition="0" objid="1567500813" subresource="FULL" dbid="9" objectname="xxxx.dbo.T_IC_AUDIT_LOG" id="lockcbc5340" mode="SIX" associatedObjectId="1567500813">
<
owner-list>
<
owner id="process998f28" mode="SIX" />
</
owner-list>
<
waiter-list>
<
waiter id="process90aa78" mode="IX" requestType="convert" />
</
waiter-list>
</
objectlock>
<
keylock hobtid="72057594137280512" dbid="9" objectname="xxxxx.dbo.T_IC_AUDIT_LOG" indexname="C_IC_AUDIT_LOG_PK" id="lockcbc7400" mode="RangeS-S" associatedObjectId="72057594137280512">
<
owner-list>
<
owner id="process90aa78" mode="RangeS-S" />
</
owner-list>
<
waiter-list>
<
waiter id="process998f28" mode="RangeI-N" requestType="wait" />
</
waiter-list>
</
keylock>
</
resource-list>
</
deadlock>
</
deadlock-list>

The solution to this problem is to convert the non-clustered index on the primary key to a clustered index.  This prevents the cross locking scenario, and is actually going to be better for performance since the data will then be logically stored by the clustered index key.

With a clustered index, the following image should show how the deadlock is prevented.

 

image

I don't currently have a reproduction of the above scenario, but I have added it to my ever growing list of things to create and post.  I am certain that I can create a demo for this problem.

 

UPDATE:

While finalizing this, a repost was made where the isolation level was changed, but a deadlock still occurred.  The issue is still the non-clustered index on the heap, and locking order.  Converting to a clustered index will fix the problem still.

Published Tuesday, November 25, 2008 1:59 PM by Jonathan Kehayias
Filed under:

Comments

No Comments
Anonymous comments are disabled

This Blog

Syndication

Powered by Community Server (Commercial Edition), by Telligent Systems
  Privacy Statement