I'm currently hunting down an issue we have with deadlocks and SQL Server. There are quite a lot of deadlocks occurring. The following deadlock graph is what I am focusing on (from the live environment):
<deadlock>
<victim-list>
<victimProcess id="process41fce08"/>
<victimProcess id="process40c9048"/>
</victim-list>
<process-list>
<process id="process41fce08" taskpriority="0" logused="0" waitresource="KEY: 5:72057595257749504 (03e6337489b1)" waittime="2133" ownerId="213210603" transactionname="SELECT" lasttranstarted="2015-09-30T09:06:29.133" XDES="0xe1d9dcb0" lockMode="RangeS-S" schedulerid="4" kpid="3608" status="suspended" spid="113" sbid="0" ecid="0" priority="0" trancount="0" lastbatchstarted="2015-09-30T09:06:29.133" lastbatchcompleted="2015-09-30T09:06:29.133" clientapp=".Net SqlClient Data Provider" hostname="MYSERVER" hostpid="1692" loginname="MYUSER" isolationlevel="serializable (4)" xactid="213210603" currentdb="5" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame procname="" line="25" stmtstart="1876" stmtend="5346" sqlhandle="0x030005007f7dca111202de0024a400000100000000000000"/>
</executionStack>
<inputbuf> Proc [Database Id = 5 Object Id = 298483071] THIS IS READ STORED PROCEDURE </inputbuf>
</process>
<process id="process40c9048" taskpriority="0" logused="0" waitresource="KEY: 5:72057595257749504 (03e6337489b1)" waittime="2137" ownerId="213210579" transactionname="SELECT" lasttranstarted="2015-09-30T09:06:29.130" XDES="0x8051fcb0" lockMode="RangeS-S" schedulerid="2" kpid="3908" status="suspended" spid="101" sbid="0" ecid="0" priority="0" trancount="0" lastbatchstarted="2015-09-30T09:06:29.130" lastbatchcompleted="2015-09-30T09:06:29.130" clientapp=".Net SqlClient Data Provider" hostname="MYSERVER" hostpid="5328" loginname="MYUSER" isolationlevel="serializable (4)" xactid="213210579" currentdb="5" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
<executionStack>
<frame procname="" line="25" stmtstart="1876" stmtend="5346" sqlhandle="0x030005007f7dca111202de0024a400000100000000000000"/>
</executionStack>
<inputbuf> Proc [Database Id = 5 Object Id = 298483071] THIS IS READ STORED PROCEDURE </inputbuf>
</process>
<process id="process11eca3708" taskpriority="0" logused="247980" waitresource="OBJECT: 5:1745427475:0 " waittime="1913" ownerId="213208999" transactionname="user_transaction" lasttranstarted="2015-09-30T09:06:28.640" XDES="0xc2f3ae90" lockMode="IX" schedulerid="3" kpid="272" status="suspended" spid="72" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2015-09-30T09:06:29.410" lastbatchcompleted="2015-09-30T09:06:29.410" clientapp=".Net SqlClient Data Provider" hostname="MYSERVER" hostpid="4172" loginname="MYUSER" isolationlevel="serializable (4)" xactid="213208999" currentdb="5" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
<executionStack>
<frame procname="" line="6" stmtstart="232" sqlhandle="0x0300050098df89558d028500b59f00000100000000000000"/>
</executionStack>
<inputbuf> Proc [Database Id = 5 Object Id = 1435099032] THIS IS READ UPDATE PROCEDURE </inputbuf>
</process>
</process-list>
<resource-list>
<keylock hobtid="72057595257749504" dbid="5" objectname="" indexname="" id="lockee29f480" mode="X" associatedObjectId="72057595257749504">
<owner-list/>
<waiter-list>
<waiter id="process41fce08" mode="RangeS-S" requestType="wait"/>
</waiter-list>
</keylock>
<keylock hobtid="72057595257749504" dbid="5" objectname="" indexname="" id="lockee29f480" mode="X" associatedObjectId="72057595257749504">
<owner-list>
<owner id="process11eca3708" mode="X"/>
</owner-list>
<waiter-list>
<waiter id="process40c9048" mode="RangeS-S" requestType="wait"/>
</waiter-list>
</keylock>
<objectlock lockPartition="0" objid="1745427475" subresource="FULL" dbid="5" objectname="" id="lock128d27d80" mode="S" associatedObjectId="1745427475">
<owner-list>
<owner id="process41fce08" mode="S"/>
</owner-list>
<waiter-list>
<waiter id="process11eca3708" mode="IX" requestType="convert"/>
</waiter-list>
</objectlock>
</resource-list>
</deadlock>
Looking at deadlock victim process id = process41fce08, which is a select stored procedure, appears to run under a Serializable transaction.
However, looking at the stack trace, the transaction scope is not used. No explicit transaction is created. A simple SqlConnection and SqlCommand is used to execute the stored procedure.
Looking at the call stack to execute the same code path on my local development machine this shows the transaction isolation level running under ReadCommitted. This information is retrieved using:
select
CASE transaction_isolation_level
WHEN 0 THEN 'Unspecified'
WHEN 1 THEN 'ReadUncommitted'
WHEN 2 THEN 'ReadCommitted'
WHEN 3 THEN 'Repeatable'
WHEN 4 THEN 'Serializable'
WHEN 5 THEN 'Snapshot'
ELSE 'Unknown'
END
FROM sys.dm_exec_sessions
where session_id = @@SPID
from inside the stored procedure. If I call:
SET TRANSACTION ISOLATION LEVEL SERIALIZABLE
in the stored procedure, I see the isolation level change in the above select. This is what I expect and what I see in my development environment:
Default Isolation Level in ADO.NET
So given that:
Something appears to be setting the Isolation Level on the live environment? The question is what is setting this or forcing it to be Serializable?
The code runs in a MVC3 Application on .NET 4.
It would appear to be down to Connection Pooling.
I noticed in the connection string we had the following:
Pooling=true; Min Pool Size=5; Max Pool Size=100; Connect Timeout=7
I created a number of unit tests to demonstrate this.
SQL Create Script
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE PROCEDURE [dbo].[usp_GetName]
(
@id int,
@TransactionIsolation varchar(30) output
)
AS
BEGIN
-- SET NOCOUNT ON added to prevent extra result sets from
-- interfering with SELECT statements.
SET NOCOUNT ON;
set @TransactionIsolation = dbo.fn_GetTransactionIsolation();
SELECT [Id]
,[Name]
,[Status]
FROM [dbo].[NameTable]
where Id = @id
END
CREATE FUNCTION [dbo].[fn_GetTransactionIsolation]
(
)
RETURNS varchar(30)
AS
BEGIN
-- Declare the return variable here
DECLARE @til varchar(30)
select @til =
CASE transaction_isolation_level
WHEN 0 THEN 'Unspecified'
WHEN 1 THEN 'ReadUncommitted'
WHEN 2 THEN 'ReadCommitted'
WHEN 3 THEN 'Repeatable'
WHEN 4 THEN 'Serializable'
WHEN 5 THEN 'Snapshot'
ELSE 'Unknown'
END
FROM sys.dm_exec_sessions
where session_id = @@SPID
-- Return the result of the function
RETURN @til
END
GO
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE TABLE [dbo].[NameTable](
[Id] [int] IDENTITY(1,1) NOT NULL,
[Name] [nvarchar](50) NOT NULL,
[Status] [int] NOT NULL,
CONSTRAINT [PK_NameTable] PRIMARY KEY CLUSTERED
(
[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_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE TABLE [dbo].[SPLog](
[Id] [int] IDENTITY(1,1) NOT NULL,
[StoredProcName] [nvarchar](50) NOT NULL,
[LogDate] [datetime] NOT NULL,
CONSTRAINT [PK_SPLog] PRIMARY KEY CLUSTERED
(
[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
Unit Tests
using System;
using System.Data;
using System.Data.SqlClient;
using System.Threading;
using System.Transactions;
using Microsoft.VisualStudio.TestTools.UnitTesting;
namespace TransactionTest
{
[TestClass]
public class UnitTest1
{
[TestMethod]
public void SPGet_NoTransaction_ShouldReturn_ReadCommitted()
{
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read())
{
}
reader.Close();
var transactionIsolation = (string)cmd.Parameters["@TransactionIsolation"].Value;
Assert.AreEqual("ReadCommitted", transactionIsolation);
}
}
}
[TestMethod]
public void SPUpdate_NoTransaction_ShouldReturn_ReadCommitted()
{
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_UpdateName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@name", "test update", SqlDbType.VarChar, 30);
AddParameter(cmd, "@status", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read())
{
}
reader.Close();
var transactionIsolation = (string)cmd.Parameters["@TransactionIsolation"].Value;
Assert.AreEqual("ReadCommitted", transactionIsolation);
}
}
}
[TestMethod]
public void SPGet_TransactionSerializable_ShouldReturn_Serializable()
{
using (var tran = new TransactionScope(
TransactionScopeOption.Required,
new TransactionOptions { IsolationLevel = System.Transactions.IsolationLevel.Serializable }))
{
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read())
{
}
reader.Close();
var transactionIsolation = (string)cmd.Parameters["@TransactionIsolation"].Value;
Assert.AreEqual("Serializable", transactionIsolation);
}
}
tran.Complete();
}
}
private static string GetConnection()
{
var builder = new SqlConnectionStringBuilder();
builder.InitialCatalog = "ACMETransactions";
builder.DataSource = ".";
builder.IntegratedSecurity = true;
builder.Pooling = true;
builder.MaxPoolSize = 100;
return builder.ToString();
}
private static void AddParameter(SqlCommand command, string name, object value, SqlDbType type, int size = -1, ParameterDirection direction = ParameterDirection.Input)
{
command.Parameters.Add(new SqlParameter
{
ParameterName = name,
SqlDbType = type,
Value = value,
Direction = direction
});
if (size != -1)
{
command.Parameters[command.Parameters.Count - 1].Size = size;
}
}
[TestMethod]
public void SPGet__MultiThread_Conflict()
{
string serializedIsolationResult = "";
string normalIsolationResult = "";
var normalThread = new Thread(new ThreadStart(() =>
{
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read()) ;
reader.Close();
normalIsolationResult = (string)cmd.Parameters["@TransactionIsolation"].Value;
}
}
}));
var serializedThread = new Thread(new ThreadStart(() =>
{
using (var tran = new TransactionScope(
TransactionScopeOption.Required,
new TransactionOptions { IsolationLevel = System.Transactions.IsolationLevel.Serializable }))
{
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read()) ;
reader.Close();
serializedIsolationResult = (string)cmd.Parameters["@TransactionIsolation"].Value;
}
normalThread.Join();
Thread.Sleep(1000);
}
tran.Complete();
}
}));
serializedThread.Start();
normalThread.Start();
serializedThread.Join();
Assert.AreEqual("ReadCommitted", normalIsolationResult);
Assert.AreEqual("Serializable", serializedIsolationResult);
}
[TestMethod]
public void SPGet__MultiThread_NoTransactionScope()
{
string serializedIsolationResult = "";
string normalIsolationResult = "";
var normalThread = new Thread(new ThreadStart(() =>
{
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read()) ;
reader.Close();
normalIsolationResult = (string)cmd.Parameters["@TransactionIsolation"].Value;
}
}
}));
var serializedThread = new Thread(new ThreadStart(() =>
{
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read()) ;
reader.Close();
serializedIsolationResult = (string)cmd.Parameters["@TransactionIsolation"].Value;
}
}
}));
serializedThread.Start();
normalThread.Start();
serializedThread.Join();
Assert.AreEqual("ReadCommitted", normalIsolationResult);
Assert.AreEqual("ReadCommitted", serializedIsolationResult);
}
[TestMethod]
public void SPGet__MultiConnection()
{
string normalIsolationResult2 = "";
string normalIsolationResult1 = "";
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read()) ;
reader.Close();
normalIsolationResult1 = (string)cmd.Parameters["@TransactionIsolation"].Value;
}
}
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read()) ;
reader.Close();
normalIsolationResult2 = (string)cmd.Parameters["@TransactionIsolation"].Value;
}
}
Assert.AreEqual("ReadCommitted", normalIsolationResult1);
Assert.AreEqual("ReadCommitted", normalIsolationResult2);
}
[TestMethod]
public void SPGet__SingleConnection()
{
string normalIsolationResult2 = "";
string normalIsolationResult1 = "";
using (var con = new SqlConnection(GetConnection()))
{
con.Open();
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read()) ;
reader.Close();
normalIsolationResult1 = (string)cmd.Parameters["@TransactionIsolation"].Value;
}
using (var cmd = new SqlCommand("usp_GetName", con))
{
cmd.CommandType = CommandType.StoredProcedure;
AddParameter(cmd, "@id", 1, SqlDbType.Int);
AddParameter(cmd, "@TransactionIsolation", 1, SqlDbType.VarChar, 30, ParameterDirection.Output);
SqlDataReader reader = cmd.ExecuteReader();
while (reader.Read()) ;
reader.Close();
normalIsolationResult2 = (string)cmd.Parameters["@TransactionIsolation"].Value;
}
}
Assert.AreEqual("ReadCommitted", normalIsolationResult1);
Assert.AreEqual("ReadCommitted", normalIsolationResult2);
}
}
}
Simply changing the GetConnection method to remove the Pooling/MaxPoolSize causes the tests to pass every time.
With these parameters some tests will fail.
I am assuming that in the live environment with the deadlocks, we are witnessing connections being reused with the transaction scope being set to Serializable elsewhere from code that executes any updates where TransactionScope is explicitly used.