BEHAVIOR/SYMPTOMS:

We recently had a customer come to us seeking help on a performance issue that he was experiencing. Understood, that there’s a web-application written in ASP.Net and was using SQL Server at the backend. During the peak usage hours, the application users were experiencing query below timeout errors and sometimes the application even seemed to hang.

 

Error:

Microsoft OLE DB Provider for ODBC Drivers error '80040e31'

[Microsoft][ODBC SQL Server Driver]Timeout expired

/cpgrams/currentusers.asp, line 22

 

We know that a query times out, when its execution time exceeds the “query timeout” value. We also know that the “query timeout” value is set in the application; if not explicitly set, the application assigns a “query timeout” value to 30 seconds. However, the main question here is: Why were the queries getting timed out?

 

We were also told that in most cases, the application web-pages in question work fine and they generally do not get timed out. The issue happens only during peak load, and that too, not always – means issue is intermittent. There were many probabilities that we could think off; but troubleshooting an issue means narrowing down to the root cause and then fix it. We started off by collecting a SQLDIAG.

 

While we were looking into the SQLDIAG data, we noticed that the time-stamps of the query timeout issues (from the SQL Server Profiler Traces) seemed to coincide with blocking chains as detected by the Blocker. Hence, we decided to start the troubleshooting the issue from a Blocking perspective. We took a sample blocking chain; here is what we found:

 

spid   status                         blocked open_tran waitresource                           

------ ------------------------------ ------- --------- ----------------------------------------

    56 suspended                           60         0 PAG: 7:1:82527                         

    60 sleeping                             0         1                                        

   132 suspended                           60         0 PAG: 7:1:138617                         

   134 suspended                           60         0 KEY: 7:72057594071351296 (7f017e10728c)

 

We identified that SPID 60 was at the head of blocking chain for a long time. It also had an open transaction. SPID 60 also had a lot of locks, the grant mode, and most of these locks were either “X” locks or “IX” locks, that are not compatible with most other locks. Hence, we started looking into the queries executed by SPID 60, from the SQL Server Profiler Traces. We noticed that a certain set of code was executed repeatedly. The set of code was:

 

Begin Transaction OuterTran

       Update Stmt

       Select Stmt(s)

 

       Begin Transaction InnerTran

              Insert Stmt(s)

Commit Transaction InnerTran

Commit Transaction OuterTran

 

While all looked well with the above code, there was something we found causing a problem. In one iteration, the Insert statement within the InnerTran got failed with the error below:

 

Error: 547, Severity: 16, State: 0

The INSERT statement conflicted with the FOREIGN KEY constraint "FK_constraint_name". The conflict occurred in database "dbname", table "schema_name.table_name", column 'column_name'.

The statement has been terminated.

 

But how can a failed DML cause blocking or even an application hang?

 

ROOT CAUSE:

To understand what the cause of the blocking was, we wrote a sample application code (similar to the customer’s code) to reproduce the issue. Here are the table structures:

 

CREATE TABLE [dbo].[tblPerson](

       [SSN] [int] NOT NULL,

       [FullName] [varchar](100) NOT NULL,

       [Country] [varchar] (100) NOT NULL,

       [NumProjects] [int] NOT NULL,

 CONSTRAINT [PK_tblPerson] PRIMARY KEY CLUSTERED

(

       [SSN] 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

 

INSERT INTO [dbo].[tblPerson] VALUES (1, 'AAA', 'XXX', 0)

INSERT INTO [dbo].[tblPerson] VALUES (2, 'BBB', 'XXX', 0)

INSERT INTO [dbo].[tblPerson] VALUES (3, 'CCC', 'YYY', 0)

INSERT INTO [dbo].[tblPerson] VALUES (4, 'DDD', 'YYY', 0)

GO

 

CREATE TABLE [dbo].[tblProjects](

       [SSN] [int] NOT NULL,

       [ProjectID] [int] NOT NULL,

       [ProjectName] [varchar](100) NOT NULL

) ON [PRIMARY]

GO

 

ALTER TABLE [dbo].[tblProjects]  WITH CHECK ADD  CONSTRAINT [FK_tblProjects_tblPerson] FOREIGN KEY([SSN])

REFERENCES [dbo].[tblPerson] ([SSN])

GO

 

ALTER TABLE [dbo].[tblProjects] CHECK CONSTRAINT [FK_tblProjects_tblPerson]

GO

 

CREATE PROC [dbo].[usp_SampleProc]

       @SSN INT,

       @ProjID INT,

       @ProjName VARCHAR(100)

AS

BEGIN

       BEGIN TRAN IT

              INSERT INTO dbo.tblProjects VALUES (@SSN, @ProjID, @ProjName)

       COMMIT TRAN IT

END

GO

 

Here is the code that we wrote. We used C#.Net:

 

using System;

using System.Collections.Generic;

using System.Linq;

using System.Text;

using System.Data;

using System.Data.SqlClient;

 

namespace ConsoleApplication1

{

    class Program

    {

        static void Main(string[] args)

        {

            int SSN = Int32.Parse(args[0].ToString());

            int ProjID = Int32.Parse(args[1].ToString());

            string ProjName = args[2].ToString();

            int NumProjects;

 

            SqlConnection MyConn = new SqlConnection();

            SqlCommand MyCmd = new SqlCommand();

            MyConn.ConnectionString = "Persist Security Info=False;Data Source=.;" +

                "Integrated Security=SSPI;Initial Catalog=TestDatabase;Application Name=MyApplication";

            try

            {

                MyConn.Open();

                Console.WriteLine("Opened connection to SQL Server.");

                MyCmd.CommandTimeout = 0;

                MyCmd.Connection = MyConn;

                try

                {

                    Console.WriteLine("Starting query execution...");

                   

                    MyCmd.CommandType = CommandType.Text;

                    MyCmd.CommandText = "BEGIN TRAN OT";

                    MyCmd.ExecuteNonQuery();

 

                    MyCmd.CommandType = CommandType.Text;

                    MyCmd.CommandText = "SELECT [NumProjects] FROM dbo.tblPerson WHERE [SSN] = " +

                        SSN.ToString();

                    try

                    {

                        NumProjects = Int32.Parse(MyCmd.ExecuteScalar().ToString());

                        NumProjects++;

                        MyCmd.CommandType = CommandType.Text;

                        MyCmd.CommandText = "UPDATE dbo.tblPerson SET [NumProjects] = " +

                            NumProjects.ToString() + " WHERE [SSN] = " + SSN.ToString();

                        MyCmd.ExecuteNonQuery();

                    }

                    catch

                    {

                        Console.WriteLine("Person not found. The SP call will fail.");

                    }

 

                    SqlParameter P_SSN = new SqlParameter("@SSN", SqlDbType.Int);

                    P_SSN.Value = SSN;

                    SqlParameter P_ProjID = new SqlParameter("@ProjID", SqlDbType.Int);

                    P_ProjID.Value = ProjID;

                    SqlParameter P_ProjName = new SqlParameter("@ProjName", SqlDbType.VarChar);

                    P_ProjName.Value = ProjName;

 

                    MyCmd.CommandType = CommandType.StoredProcedure;

                    MyCmd.Parameters.Add(P_SSN);

                    MyCmd.Parameters.Add(P_ProjID);

                    MyCmd.Parameters.Add(P_ProjName);

                    MyCmd.CommandText = "usp_SampleProc";

                    MyCmd.ExecuteNonQuery();

                    MyCmd.Parameters.Clear();

 

                    MyCmd.CommandType = CommandType.Text;

                    MyCmd.CommandText = "COMMIT TRAN OT";

                    MyCmd.ExecuteNonQuery();

 

                    Console.WriteLine("Ended query execution");

                }

                catch (Exception ExI)

                {

                    Console.WriteLine("Error from Inner Catch :: " + ExI.Message.ToString());

                }

                finally

                {

                    MyConn.Close();

                    MyConn.Dispose();

                    Console.WriteLine("Connection Object Destroyed.");

                }

 

            }

            catch (Exception ExO)

            {

                Console.WriteLine("Error from Outer Catch :: " + ExO.Message.ToString());

            }

            finally

            {

                Console.ReadKey(true);

            }

 

        }

    }

}

 

We executed the application using the values of 1 for SSN, 1 for ProjectID and “Project1” for ProjectName. Here is what we got in the Profiler:

image

We now executed “sp_lock 65”, and here’s what we got:

 

spid   dbid   ObjId       IndId  Type Resource                         Mode     Status

------ ------ ----------- ------ ---- -------------------------------- -------- ------

65     11     0           0      DB                                    S        GRANT

 

We now, entered data so that we can simulate a Foreign Key violation. We executed the application using the values of 7 for SSN, 3 for ProjectID and “Project3” for ProjectName, here’s what we got on the profiler trace:

 

image

Now, we noticed that the Outer Transaction was not affected. The transaction was open as confirmed by sys.sysprocesses:

spid   kpid   dbid   open_tran program_name

------ ------ ------ --------- -------------

65     0      11     1         MyApplication

 

“sp_lock 65” showed the following locks:

 

spid   dbid   ObjId       IndId  Type Resource                         Mode     Status

------ ------ ----------- ------ ---- -------------------------------- -------- ------

65     11     0           0      DB                                    S        GRANT

65     11     85575343    0      PAG  1:114                            IX       GRANT

65     11     85575343    0      TAB                                   IX       GRANT

65     11     85575343    0      RID  1:114:1                          X        GRANT

 

This meant that locks were held and could result in blocking other connections that tried to access the object ID85575343 (the table tblProjects in our case). The transaction was rolled back after quite a long time, when the connection was finally terminated:

 

We came to the following conclusion:

·         While the inner transaction got terminated, there was no exception-handle written for the outer transaction.

·         Accordingly, the Parent Transaction continued to remain open, holding locks on key tables. This caused the blocking.

·         Further, the Parent Transaction only got terminated once the Connection Timeout (defined in .Net application) was reached after 500 seconds.

 

RESOLUTION:

 

Simple code changes could help in avoiding the above issue. We could just add an exception handle using either of options:

 

Option 1.  Use SET XACT_ABORT ON. SQL Server will automatically roll back the current transaction when a Transact-SQL statement raises a run-time error:

 

ALTER PROC [dbo].[usp_SampleProc]

       @SSN INT,

       @ProjID INT,

       @ProjName VARCHAR(100)

AS

BEGIN

       SET XACT_ABORT ON

       BEGIN TRAN IT

              INSERT INTO dbo.tblProjects VALUES (@SSN, @ProjID, @ProjName)

       COMMIT TRAN IT

       SET XACT_ABORT OFF

END

GO

 

Example: Using SET XACT_ABORT in a transaction - http://technet.microsoft.com/en-us/library/ms188792(SQL.90).aspx

 

Option 2: Handle the error condition in code:

 

catch (Exception ExI)

{

    Console.WriteLine("Error from Inner Catch :: " + ExI.Message.ToString());

    MyCmd.Parameters.Clear();

    MyCmd.CommandType = CommandType.Text;

    MyCmd.CommandText = "ROLLBACK TRAN OT";

    MyCmd.ExecuteNonQuery();

}

 

Hopefully, this post will allow you to better code your application to avoid blocking.

 

Suhas De & Varun Dhawan

Support Engineer, Microsoft SQL Server.


Reviewed by
Saket Suman
TL, Microsoft SQL Server