Tuesday, October 26, 2010

Deadlock two ways (Microsoft SQL Server)

Think of "Duck two-ways" or some other delicious meal. This is as tasty ;-)

If you have done any development with Microsoft SQL Server with even a moderate amount of concurrent processing, then you have probably witnessed the dreaded:
Transaction (Process ID 42) was deadlocked on lock resources with another process and has been chosen as the deadlock victim
This indicates that Microsoft SQL Server has detected a deadlock and has killed one of the processes to eliminate the stale mate. Let's go through two very different deadlock conditions that have the same central theme. I have found these to be extremely common in production.

Intuitively deadlock is a "deadly embrace" that occurs when two resources are being contended over. Thus, people are often surprised when they get deadlocks and "they weren't touching the same records!". Unfortunately, in traditional pessimistic locking solutions to concurrency control, other records must be locked to guarantee ACID properties. There are other solutions to concurrency control (MVCC is the one everyone reaches for) that avoid most/all of this. However, MSSQL by default employs a pessimistic approach. Also, I don't mean to sound as if I'm picking on MSSQL-- the principles below are true in a number of database implementations. DB/2 is also particularly nasty with pessimistic locking style deadlocks. The two presented below were reported to the JTDS forums, and are from real production.

Deadlock I


This is the common unicode "mismatch" problem. This has been covered on blogs a lot. I am going to use this as a way to describe how to research deadlocks. But if you're already bored, go ahead and skip to Deadlock II
Here is a table definition (slightly changed for brevity):

CREATE TABLE [PM1](
[ID] [bigint] IDENTITY(1,1) NOT NULL,
[KEYNAME] [varchar](50) NOT NULL,
[VALUE] [varchar](255) NULL,
CONSTRAINT [PK_PM1] PRIMARY KEY CLUSTERED
(
[ID] ASC
))
CREATE NONCLUSTERED INDEX [pmkv_idx] ON [PM1]
(
[KEYNAME] ASC,
)
Now we execute multiple, concurrent:
DELETE FROM PM1 WITH (ROWLOCK) WHERE KEYNAME = @P0

And we get a deadlock! Let's familiarize ourselves with some technical details and terms:

Clustered and Non-Clustered Indexes


There are two database structures for this DDL. One primary, clustered index, which has a key [ID]. And a secondary, non-clustered index, which has a key [KEYNAME]. A "clustered" index means that all of the data, the entire record, is stored in the leaf of the index. It is still an index--it is still searchable by [ID], but when it gets to a leaf, the entire data record is physically stored there. This is different from a secondary or non-clustered index in which the leaf of the index contains some kind of reference to the whole data record. In our secondary index, the index is "searchable" by [KEYNAME], but in the leaves of the index, the "reference" is actually the primary key value (ID), which can be used then to "search" the primary, clustered index. This is how databases use secondary indexes-- they find matching data with the index, then do a bookmark lookup, which is a join, into the clustered index to get the rest of the data.

Seeking vs Scanning


There are different actions the engine can perform on these structures: the engine can scan the index, in which case it will start somewhere (often the beginning) and start reading each record in order. As these indexes a B+-Trees, the leaf level is a doubly linked list. Thus, from a single leaf node, you can read sibling records in order without having to go "up and down" the index levels. Scanning is expensive as it is an O(n) operation which degrades as the number of records increases.

The engine can seek the index, in which case it will use a binary search to locate a leaf node (record). This is much preferable as it is a O(log n) operation-- and the base of that log is very high (the number of records per page). Thus seeking is why we put indexes on tables-- to take advantage of the "quick" searching.

Getting Information about your deadlock


In Microsoft SQL Server (2005+) there is a useful report that can give you good details about your deadlock. Without this information, it's very difficult to understand what's really happening. You can get this information two ways
  • SQL Server Profiler, capturing the Deadlock event
  • Enable Trace Flag 1222
I find it generally useful to enable T1222 as a startup parameter for SQL Server, so that whenever a deadlock occurs, it dumps the details to the SQL Server error log file. This is great, and incurs negligible performance overhead.

Trace 1222 Output


Let's look at the 1222 output and see what actually happened. There are two sections to the 1222: (1) the processes involved, (2) the wait-for graph, which shows which locks are acquired which are trying to be acquired. Here is an abbreviated 1222 for this deadlock:

<deadlock victim="process3dcab08">
 <process-list>
  <process id="process3dcab08" ...>
   <executionStack>
    <frame ... >DELETE FROM PM1 WITH (ROWLOCK) WHERE AND KEYNAME = @P0 </frame>
   </executionStack>
   <inputbuf>(@P0 nvarchar(4000))DELETE FROM PM1 WITH (ROWLOCK) WHERE KEYNAME = @P0 </inputbuf>
  </process>
  <process id="process3de1198" >
   ... (same as previous process) ...
  </process>
 </process-list>
 <resource-list>
  <keylock ... objectname="DB1.dbo.PM1" indexname="PM_IDidx" ... mode="X" ... >
   <owner-list>
    <owner id="process3de1198" mode="X"/>
   </owner-list>
   <waiter-list>
    <waiter id="process3dcab08" mode="U" requestType="wait"/>
   </waiter-list>
  </keylock>
  <keylock ... objectname="DB1.dbo.PM1" indexname="PM_IDidx" ... mode="X" ... >
   <owner-list>
    <owner id="process3dcab08" mode="X"/>
   </owner-list>
   <waiter-list>
    <waiter id="process3de1198" mode="U" requestType="wait"/>
   </waiter-list>
  </keylock>
 </resource-list>
</deadlock>

The process-list section describes all of the processes (concurrent executions) involved. I have colored one blue and one green to help distinguish them. So as we see each is holding an X (exclusive) lock, which the other is trying to get a U (update) lock for.

The database must hold an X lock before actually modifying a record, thus we expect this to be involved. However, a U lock is unexpected. Update locks are an "in between" lock, which are used by the database when scanning for potential records that need to be updated. In this case, a U lock is acquired before checking the value to see if it matches your WHERE clause. If it does, then the U is "upgraded" to an X lock, if not, then it is released. However, our WHERE claue has KEYNAME = @P0, which is indexed. Thus, we shouldn't be scanning anything-- we should be seeking on the index. When seeking-- the database goes exactly to the records which qualify, and thus X locks are requested to begin with. Thus, we expect to see only X locks from the statements above.

So what happened?


The answer is subtle: look at the input buffer for the delete statement:

<inputbuf>(@P0 nvarchar(4000))DELETE FROM PM1 WITH (ROWLOCK) WHERE KEYNAME = @P0 </inputbuf>

The parameter for the delete statement was declared by the driver as nvarchar, but if you look back at the DDL, you will see that the KEYNAME column is declared as varchar.

The NVARCHAR datatype is a unicode text datatype, whereas VARCHAR is non-unicode, 8-bit character datatype. The engine cannot directly compare an nvarchar value to a varchar value-- it must use a conversion. This conversion makes the where clause predicate not sargable, and that disallows the optimizer from seeking on it. Instead it scans the whole index, one record at a time, and for each one, requests a U lock, converts and checks the value, releases the U lock. Thus, for every delete of a single record, every record must be checked with an expensive, conflicting lock. And as seen in our case, two concurrent deletes happen to be checking and ran into each other.

The solution


So why did the driver do that? Well this was a Java application, and in Java strings are unicode by default. By default, the driver binds strings to their unicode counterpart. However, there is a setting on the driver's connection url, which instructs the driver to bind to non-unicode instead. The key is that you want to ensure that the driver is sending parameters the same as the underlying schema is defined. For JTDS the setting is sendStringParametersAsUnicode and it defaults to TRUE. Thus, if your schema is defined with all VARCHARs and you are using them in indexes, then you want to ensure this property is set to FALSE in your connection url. Here is an example of a connection url that forces the driver to send them as varchar instead of nvarchar:

jdbc:jtds:sqlserver://mssql01:1433/DB1;sendStringParametersAsUnicode=false

Deadlock II


This deadlock is a little less common, but interesting, because it also has an "unexpected" wait-for graph in the 1222 output. The schema was jBPM, which may be familiar. I need to see if someone has already fixed this in jBPMs delivered schema.

Trace 1222 Output


First, let's look at the 1222 trace:

<deadlock victim="process3de0868">
 <process-list>
  <process id="process3deb08" ...>
   ...
   <inputbuf>(@P0 bigint,@P1 int)delete from JBPM4_SWIMLANE where DBID_= @P0 and DBVERSION_= @P1</inputbuf>
  </process>
  <process id="process3de0868" ...>
   ... same as other process ...
  </process>
 </process-list>
 <resource-list>
  <keylock ... objectname="dbo.JBPM4_TASK" indexname="PK__JBPM4_TASK__2BFE89A6" mode="X" ...>
   <owner-list>
    <owner id="process3deb08" mode="X"/>
   </owner-list>
   <waiter-list>
    <waiter id="process3de0868" mode="S" requestType="wait"/>
   </waiter-list>
  </keylock>
  <keylock ... objectname="dbo.JBPM4_TASK" indexname="PK__JBPM4_TASK__2BFE89A6" mode="X" ...>
   <owner-list>
    <owner id="process3de0868" mode="X"/>
   </owner-list>
   <waiter-list>
    <waiter id="process3deb08" mode="S" requestType="wait"/>
   </waiter-list>
  </keylock>
 </resource-list>
</deadlock>

So we have two workers executing a delete by primary key... and they're deadlocking on S locks!? An S (shared) lock is used when the database needs to get a consistent read on something. Thus, by default, when you execute SELECT statements, shared locks are being issued under the covers to ensure read consistency (w.r.t the isolation level you're running at).

So what happened?


There is a hint in the wait-for graph that shows the problem: Look at the keylock that is being contended-- the indexname is PK__JBPM4_TASK__2BFE89A6. This is an auto-generated name for the primary, clustered index for the JBPM4_TASK table. We're deleting from the SWIMLANE table, so why would there be any locks on the TASK table? The TASK table has a foreign key reference (field swimlane_) to the SWIMLANE table. Thus, when you delete a SWIMLANE record, the database must ensure that there are no records referring to the SWIMLANE record. If there are, then the delete cannot proceed, because it would be a foreign key constraint violation. To do this check, the database needs to find records in the JBPM4_TASK table WHERE swimlane_ = id of swimlane being deleted. This read will be done using S locks to ensure consistency. Unfortunately, the JBPM4_TASK table does NOT have a secondary index on the swimlane_ column. Thus, the only option the database has is to scan the entire table by primary, clustered index. Thus, for each record, a S lock must be acquired, the record evaluated for the WHERE clause, and then the S lock is released. Each one of these is a deadlock opportunity if there are concurrent operations touching the TASK table.

The Solution


Adding an index on the swimlane_ column in the TASK table will reduce the n deadlock opportunities to 1, which is a significant improvement-- not to mention the performance improvement.

The Overall Theme


While these are very different deadlocks, the theme is the same: unintended scans. Scans are not only a performance problem, but a deadlock problem, as you increase the number of times that you request conflicting locks while holding locks. Thus, take care when considering which indexes to create-- its a tricky problem with many factors.

Steve