SQL Blocking – Troubleshooting In Transaction User Interactions

This post explains how to troubleshoot and fix applications causing SQL Blocking doing user interactions in SQL Transactions.

Locking of resources like rows, tables, keys, pages etc is by design and a necessity in SQL server, so that the transactions are properly processed and data is always in a consistent state. Generally locks are held for a very short period of time. They are released as soon as possible. In addition to the resources that can be locked, there are lock modes like Shared Lock (S), Update Lock (U), Exclusive Lock (X), etc.

Shared locks are used when reading rows. This lock ensures that rows are not modified while being read. However, two or more concurrent transactions can read data simultaneously. Generally, although there are exceptions, Shared locks on rows are released as soon as row is read.

Exclusive locks are used when modifying data using INSERT, UPDATE or DELETE. When a resource is exclusively locked, no other transaction can read or write that resource until lock is released. Once acquired, Exclusive locks are released only at the end of transactions.

This behavior of locking can lead to SQL Blocking when locks are held for a longer period of time. So it is always recommended to keep transactions as short as possible. Long running queries inside the transaction should be avoided.

Transaction control statements are not just limited to stored procedures. Transaction can also be started, committed and roll backed from a client application. In this case, it’s not just queries in transaction that can increase running time of transaction, but the application itself can also delay transaction. It is highly recommended to avoid any user interaction in a transaction. User’s input should be taken before starting the transaction. Waiting for user’s input can significantly increase the time for which locks are held blocking other transactions or even simple read operations.

Discovering SQL Blocking due User Interaction in Transaction

As a first line of action, as soon as the problem is reported, we should look for running processes and locks held.

Our options are:

  • Activity Monitor

If you can manage to run Activity Monitor on server then you get most of the information required to get an understanding of the problem. However if server is under high load you may not be run activity monitor.

  • sp_who2

This will list a lot of useful information for all sessions on server. Blocked sessions can be identified by their status as “Suspended” and some SPID in “BlkBy” column. An already blocked session can also be blocking some other sessions. So it is important to identify head of this blocking chain. This sometime gets very challenging with sp_who2.

  • sp_who2_blocks with Head Blocker and other details

Following script will give a similar output as sp_who2. But it includes additional columns for Head Blocker and Active Transaction, so as to speed up the process of nailing down of blocking issue. The session with “Head Blocker = 1”, is the session which is blocking other sessions. Let’s call this script sp_who2_blocks.


SELECT
[SPID] = s.session_id,
[Login] = s.login_name,
[Host Name] = ISNULL(s.host_name, N''),
[Net Address] = ISNULL(c.client_net_address, N''),
[DB] = ISNULL(db_name(p.dbid), N''),
[Task State] = ISNULL(t.task_state, N''),
[Command] = ISNULL(r.command, N''),
[Application] = ISNULL(s.program_name, N''),
[Blk By] = ISNULL(CONVERT (varchar, w.blocking_session_id), ''),
[H.Blkr] =
CASE
-- session has an active request, is blocked, but is blocking others or session is idle but has an open tran and is blocking others
WHEN r2.session_id IS NOT NULL AND (r.blocking_session_id = 0 OR r.session_id IS NULL) THEN '1'
-- session is either not blocking someone, or is blocking someone but is blocked by another party
ELSE ''
END,
[Active Transaction] = ISNULL(tr.transaction_id, N''),
[Wait Time (ms)] = ISNULL(w.wait_duration_ms, 0),
[Wait Type] = ISNULL(w.wait_type, N''),
[Wait Resource] = ISNULL(w.resource_description, N''),
[User Process] = CONVERT(CHAR(1), s.is_user_process),
[Total CPU (ms)] = s.cpu_time,
[Total Physical I/O (MB)] = (s.reads + s.writes) * 8 / 1024,
[Memory Use (KB)] = s.memory_usage * 8192 / 1024,
[Login Time] = s.login_time,
[Last Request Start Time] = s.last_request_start_time,
[Execution Context ID] = ISNULL(t.exec_context_id, 0),
[Request ID] = ISNULL(r.request_id, 0),
[Workload Group] = ISNULL(g.name, N'')
FROM sys.dm_exec_sessions s
LEFT OUTER JOIN sys.dm_exec_connections c ON (s.session_id = c.session_id)
LEFT OUTER JOIN sys.dm_exec_requests r ON (s.session_id = r.session_id)
LEFT OUTER JOIN sys.dm_os_tasks t ON (r.session_id = t.session_id AND r.request_id = t.request_id)
LEFT OUTER JOIN sys.dm_tran_session_transactions tr ON (s.session_id = tr.session_id)
LEFT OUTER JOIN
(
-- In some cases (e.g. parallel queries, also waiting for a worker), one thread can be flagged as
-- waiting for several different threads. This will cause that thread to show up in multiple rows
-- in our grid, which we don't want. Use ROW_NUMBER to select the longest wait for each thread,
-- and use it as representative of the other wait relationships this thread is involved in.
SELECT *, ROW_NUMBER() OVER (PARTITION BY waiting_task_address ORDER BY wait_duration_ms DESC) AS row_num
FROM sys.dm_os_waiting_tasks
) w ON (t.task_address = w.waiting_task_address) AND w.row_num = 1
LEFT OUTER JOIN sys.dm_exec_requests r2 ON (s.session_id = r2.blocking_session_id)
LEFT OUTER JOIN sys.dm_resource_governor_workload_groups g ON (g.group_id = s.group_id)--TAKE THIS dmv OUT TO WORK IN 2005
LEFT OUTER JOIN sys.sysprocesses p ON (s.session_id = p.spid)
ORDER BY s.session_id;

If the head blocker session’s Task State is “running” then it means some query is running and it may be some performance issue that it’s taking a long time to complete. In such cases it is required to optimize queries involved in transactions.

However, if the head blocker session’s Task State is not “running” or is “sleeping” or nothing listed in that column, then it means that it may be a case of user interaction in transaction and SQL server is just waiting for application for next SQL commands and to finally call a commit or roll back on the transaction. sp_who2_blocks outputs “Active Transaction” column for each session. A non-zero value in this column gives you the transaction_id of the transaction waiting for commands from application.

Quick Temporary Solutions:

Once you find the head blocker you have some options to quickly resolve the problem, but temporarily:

  1. If possible kill that SPID. This will resolve the problem immediately. But it will surface again when the same business operation is repeated.
  2. Before killing or immediately after killing, if possible contact user and simply ask for what exact business operation is being run. You can identify user and application using following columns in sp_who2_blocks script.
    1. Host Name          –             Name of Client Computer
    2. Login                    –             SQL Login being used
    3. Net Address        –             IP Address of Computer
    4. Database             –             Most of the times database name help in identifying Application
    5. Application         –             Name of the Application
  3. Start a trace on that SPID and wait or ask user to complete the transaction. This will at least give you a list of SQL statements or Stored Procedures that ran after application resumed the transaction. Advantage of not killing the SPID is that you get an idea of what business operation was performed under this transaction. However you will only see statements in trace that executed after you started trace. Even these statements can be very helpful in identifying the exact business operation. Doing so is easy with Activity Monitor. Just right click on the process and select “Trace Process in SQL Server Profiler”. Or you can also start a server side trace using following script. Just set the SPID and database filter and then run the script on server.

Running the Trace

As soon as you find SPID of Head Blocker, you should start tracing that SPID in SQL Profiler. Your trace should include events mentioned in table below. If it’s not possible to start trace immediately and the blocking process needs to be killed, then you can start a trace later on same database, but make sure you remove any SPID filter in trace script. This trace can be run for a longer period like 2-8 hours. You can then later analyze this trace to find out long running transactions and transactions which are waiting for user input.

Following script will start a server side trace with events listed below.

HeadingEvent

Event Class

Description
SessionsExisting Connection

17

Lists the properties of existing user connections when the trace was started.
Security AuditAudit Login

14

A user Logs in
Security AuditAudit Logout

15

A user Logs out
TSQLSQL:BatchCompleted

12

Indicates that the Transact-SQL batch call has completed.
Stored ProceduresRPC:Completed

10

Indicates that a remote procedure call has been completed.
TransactionsSQLTransaction

50

Monitor when transactions begin and are completed.
Stored Procedures(Optional)SP:StmtCompleted(Optional)

45

Indicates that a Transact-SQL statement within a stored procedure has completed.
LocksLock:Escalation

60

Indicates that a finer-grained lock has been converted to a coarser-grained lock.
LocksLock:Timeout (timeout > 0)

189

Indicates that a request for a lock on a resource, such as a page, has timed out because another transaction is holding a blocking lock on the required resource.
  • SP:StmtCompleted – This is optional. As this event will log each and every SQL Statement executed in stored procedures, it will increase log size dramatically.

By default, following script will run a trace for maximum 8 hours. It will create 30 files each of 200 MB. You can modify the parameters.

To enable SPID filter uncomment following line:


--exec sp_trace_setfilter @TraceID, 12, 0, 0, 53

To enable Database Name filter uncomment following line:


--exec sp_trace_setfilter @TraceID, 35, 0, 6, N'1_test'

 

/****************************************************/
/* Created By : SQL Profiler */
/* Modified By : Dinesh Sharma */
/****************************************************/

-- Create a Queue

declare @rc int
declare @TraceID int
declare @maxfilesizeinMB bigint
declare @hourstorun int
declare @maxfiles int

set @maxfilesizeinMB = 200 -- Restrict Maximum File Size to 200 MB
set @maxfiles = 30 -- Create a Maximum of 30 files (Total : 30 x 200 MB)
set @hourstorun = 8 -- Run trace for maximum 8 hours

DECLARE @EndTime DATETIME
DECLARE @OutputFileName NVARCHAR(256)

SET @OutputFileName = 'c:\temp\myserver_1_test_app_block_' +
 CONVERT(VARCHAR(20), GETDATE(),106) +
 REPLACE(CONVERT(VARCHAR(20), GETDATE(),108),':','')

SET @EndTime = DATEADD(mi,(@hourstorun * 60),getdate())

exec @rc = sp_trace_create @TraceID output, 2, @OutputFileName, @maxfilesizeinMB, NULL, @maxfiles -- Start new file
if (@rc != 0) goto error

-- Set the events
declare @on bit
set @on = 1

-- Lock:Escalation Event Class
/*-------------------------------------------------*/
exec sp_trace_setevent @TraceID, 60, 32, @on
exec sp_trace_setevent @TraceID, 60, 56, @on
exec sp_trace_setevent @TraceID, 60, 9, @on
exec sp_trace_setevent @TraceID, 60, 57, @on
exec sp_trace_setevent @TraceID, 60, 10, @on
exec sp_trace_setevent @TraceID, 60, 11, @on
exec sp_trace_setevent @TraceID, 60, 35, @on
exec sp_trace_setevent @TraceID, 60, 4, @on
exec sp_trace_setevent @TraceID, 60, 12, @on
exec sp_trace_setevent @TraceID, 60, 6, @on
exec sp_trace_setevent @TraceID, 60, 14, @on
exec sp_trace_setevent @TraceID, 60, 22, @on

-- Lock:Timeout (timeout > 0) Event Class
/*-------------------------------------------------*/
exec sp_trace_setevent @TraceID, 189, 15, @on
exec sp_trace_setevent @TraceID, 189, 32, @on
exec sp_trace_setevent @TraceID, 189, 56, @on
exec sp_trace_setevent @TraceID, 189, 1, @on
exec sp_trace_setevent @TraceID, 189, 9, @on
exec sp_trace_setevent @TraceID, 189, 57, @on
exec sp_trace_setevent @TraceID, 189, 2, @on
exec sp_trace_setevent @TraceID, 189, 10, @on
exec sp_trace_setevent @TraceID, 189, 11, @on
exec sp_trace_setevent @TraceID, 189, 35, @on
exec sp_trace_setevent @TraceID, 189, 4, @on
exec sp_trace_setevent @TraceID, 189, 12, @on
exec sp_trace_setevent @TraceID, 189, 13, @on
exec sp_trace_setevent @TraceID, 189, 6, @on
exec sp_trace_setevent @TraceID, 189, 14, @on
exec sp_trace_setevent @TraceID, 189, 22, @on

-- Audit Login Event Class
/*-------------------------------------------------*/
exec sp_trace_setevent @TraceID, 14, 8, @on
exec sp_trace_setevent @TraceID, 14, 1, @on
exec sp_trace_setevent @TraceID, 14, 9, @on
exec sp_trace_setevent @TraceID, 14, 2, @on
exec sp_trace_setevent @TraceID, 14, 6, @on
exec sp_trace_setevent @TraceID, 14, 10, @on
exec sp_trace_setevent @TraceID, 14, 14, @on
exec sp_trace_setevent @TraceID, 14, 11, @on
exec sp_trace_setevent @TraceID, 14, 35, @on
exec sp_trace_setevent @TraceID, 14, 12, @on

-- Audit Logout Event Class
/*-------------------------------------------------*/
exec sp_trace_setevent @TraceID, 15, 15, @on
exec sp_trace_setevent @TraceID, 15, 8, @on
exec sp_trace_setevent @TraceID, 15, 16, @on
exec sp_trace_setevent @TraceID, 15, 9, @on
exec sp_trace_setevent @TraceID, 15, 17, @on
exec sp_trace_setevent @TraceID, 15, 6, @on
exec sp_trace_setevent @TraceID, 15, 10, @on
exec sp_trace_setevent @TraceID, 15, 14, @on
exec sp_trace_setevent @TraceID, 15, 18, @on
exec sp_trace_setevent @TraceID, 15, 11, @on
exec sp_trace_setevent @TraceID, 15, 35, @on
exec sp_trace_setevent @TraceID, 15, 12, @on
exec sp_trace_setevent @TraceID, 15, 13, @on

-- ExistingConnection Event Class
/*-------------------------------------------------*/
exec sp_trace_setevent @TraceID, 17, 8, @on
exec sp_trace_setevent @TraceID, 17, 1, @on
exec sp_trace_setevent @TraceID, 17, 9, @on
exec sp_trace_setevent @TraceID, 17, 2, @on
exec sp_trace_setevent @TraceID, 17, 6, @on
exec sp_trace_setevent @TraceID, 17, 10, @on
exec sp_trace_setevent @TraceID, 17, 14, @on
exec sp_trace_setevent @TraceID, 17, 11, @on
exec sp_trace_setevent @TraceID, 17, 35, @on
exec sp_trace_setevent @TraceID, 17, 12, @on

-- RPC:Completed Event Class
/*-------------------------------------------------*/
exec sp_trace_setevent @TraceID, 10, 15, @on
exec sp_trace_setevent @TraceID, 10, 8, @on
exec sp_trace_setevent @TraceID, 10, 16, @on
exec sp_trace_setevent @TraceID, 10, 1, @on
exec sp_trace_setevent @TraceID, 10, 9, @on
exec sp_trace_setevent @TraceID, 10, 17, @on
exec sp_trace_setevent @TraceID, 10, 2, @on
exec sp_trace_setevent @TraceID, 10, 10, @on
exec sp_trace_setevent @TraceID, 10, 18, @on
exec sp_trace_setevent @TraceID, 10, 34, @on
exec sp_trace_setevent @TraceID, 10, 11, @on
exec sp_trace_setevent @TraceID, 10, 35, @on
exec sp_trace_setevent @TraceID, 10, 4, @on
exec sp_trace_setevent @TraceID, 10, 12, @on
exec sp_trace_setevent @TraceID, 10, 13, @on
exec sp_trace_setevent @TraceID, 10, 6, @on
exec sp_trace_setevent @TraceID, 10, 14, @on

-- SP:StmtCompleted Event Class
/*-------------------------------------------------*/
--exec sp_trace_setevent @TraceID, 45, 8, @on
--exec sp_trace_setevent @TraceID, 45, 16, @on
--exec sp_trace_setevent @TraceID, 45, 1, @on
--exec sp_trace_setevent @TraceID, 45, 9, @on
--exec sp_trace_setevent @TraceID, 45, 17, @on
--exec sp_trace_setevent @TraceID, 45, 10, @on
--exec sp_trace_setevent @TraceID, 45, 18, @on
--exec sp_trace_setevent @TraceID, 45, 34, @on
--exec sp_trace_setevent @TraceID, 45, 11, @on
--exec sp_trace_setevent @TraceID, 45, 35, @on
--exec sp_trace_setevent @TraceID, 45, 4, @on
--exec sp_trace_setevent @TraceID, 45, 12, @on
--exec sp_trace_setevent @TraceID, 45, 13, @on
--exec sp_trace_setevent @TraceID, 45, 6, @on
--exec sp_trace_setevent @TraceID, 45, 14, @on
--exec sp_trace_setevent @TraceID, 45, 15, @on

-- SQL:BatchCompleted Event Class
/*-------------------------------------------------*/
exec sp_trace_setevent @TraceID, 12, 15, @on
exec sp_trace_setevent @TraceID, 12, 8, @on
exec sp_trace_setevent @TraceID, 12, 16, @on
exec sp_trace_setevent @TraceID, 12, 1, @on
exec sp_trace_setevent @TraceID, 12, 9, @on
exec sp_trace_setevent @TraceID, 12, 17, @on
exec sp_trace_setevent @TraceID, 12, 6, @on
exec sp_trace_setevent @TraceID, 12, 10, @on
exec sp_trace_setevent @TraceID, 12, 14, @on
exec sp_trace_setevent @TraceID, 12, 18, @on
exec sp_trace_setevent @TraceID, 12, 11, @on
exec sp_trace_setevent @TraceID, 12, 35, @on
exec sp_trace_setevent @TraceID, 12, 4, @on
exec sp_trace_setevent @TraceID, 12, 12, @on
exec sp_trace_setevent @TraceID, 12, 13, @on

-- SQLTransaction Event Class
/*-------------------------------------------------*/
exec sp_trace_setevent @TraceID, 50, 15, @on
exec sp_trace_setevent @TraceID, 50, 8, @on
exec sp_trace_setevent @TraceID, 50, 1, @on
exec sp_trace_setevent @TraceID, 50, 9, @on
exec sp_trace_setevent @TraceID, 50, 6, @on
exec sp_trace_setevent @TraceID, 50, 10, @on
exec sp_trace_setevent @TraceID, 50, 14, @on
exec sp_trace_setevent @TraceID, 50, 34, @on
exec sp_trace_setevent @TraceID, 50, 11, @on
exec sp_trace_setevent @TraceID, 50, 35, @on
exec sp_trace_setevent @TraceID, 50, 4, @on
exec sp_trace_setevent @TraceID, 50, 12, @on
exec sp_trace_setevent @TraceID, 50, 13, @on
exec sp_trace_setevent @TraceID, 50, 21, @on

-- Set the Filters

exec sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Server Profiler'

--exec sp_trace_setfilter @TraceID, 12, 0, 0, 53 -- SPID Equals Filter
--exec sp_trace_setfilter @TraceID, 12, 1, 0, 53 -- More SPID Equals Filter

--exec sp_trace_setfilter @TraceID, 35, 0, 6, N'1_test' -- Database Name Like Filter
--exec sp_trace_setfilter @TraceID, 35, 1, 6, N'2_test' -- More Database Name Like Filter

-- Set the trace status to start
exec sp_trace_setstatus @TraceID, 1

-- display trace id for future references
select [email protected]
SELECT * FROM ::fn_trace_getinfo(NULL)
goto finish

error:
select [email protected]

finish:
go

Difference between RPC:Completed and SQL:BatchCompleted

Most of the above events seem obvious. But why we need both RPC:Completed and SQL:BatchCompleted? Why is it that some calls from application listed as RPC:Completed and some as SQL:BatchCompleted?

RPC:Completed is logged when application calls a stored procedure. Following is a RPC call to SQL Server.


SqlCommand sqlCmd2 = new SqlCommand("insertuserdata", sqlConn, sqlTrans);
sqlCmd2.CommandType = CommandType.StoredProcedure;
sqlCmd2.Parameters.AddWithValue("name", spousename);
sqlCmd2.Parameters.AddWithValue("age", 23);
sqlCmd2.ExecuteNonQuery();

In above case the command type of SqlCommand is “StoredProcedure”.

SQL:BatchCompleted is logged when application sends direct SQL statements to SQL server. You may also see batch calls to SQL server when application uses ADO.NET, or ADODB RecordSets. Following is a SQL Batch call from application to SQL server.


SqlCommand sqlCmd2 = new SqlCommand("insert into userdata values('" + spousename + "',23)", sqlConn, sqlTrans);

In above case the default command type of SqlCommand is “Text”.

Using the Trace File without Stopping the Trace

If you want to analyzing the trace file without stopping the trace you can make a copy of the trace file while trace is running. You can then analyze the copy of the trace file.

Stopping the Trace

Use the following script to stop the trace completely. Make sure you provide correct traceid.


--See the Running trace
SELECT * FROM ::fn_trace_getinfo(NULL)

-- Stop the Running Trace
EXEC sp_trace_setstatus @traceid = 3 , @status = 0

-- Delete the Running trace
EXEC sp_trace_setstatus @traceid = 3 , @status = 2

A Simple Case of SQL Blocking due to Application

Following is a simple transaction from an application:


SqlTransaction sqlTrans = null;
 using (SqlConnection sqlConn = new SqlConnection(myConnectionString))
 {
 sqlConn.Open();
 sqlTrans = sqlConn.BeginTransaction();
 try
 {
 SqlCommand sqlCmd1 = new SqlCommand("insert into userdata values('John',25)", sqlConn, sqlTrans);
 sqlCmd1.ExecuteNonQuery();
 string spousename = Interaction.InputBox("Please provide your Spouse's name?", "Max Value", string.Empty, -1, -1);
 SqlCommand sqlCmd2 = new SqlCommand("insert into userdata values('" + spousename + "',23)", sqlConn, sqlTrans);
 sqlCmd2.ExecuteNonQuery();
 sqlTrans.Commit();
 }
 catch (Exception ex)
 {
 MessageBox.Show(ex.Message);
 sqlTrans.Rollback();
 }
 finally
 {
 sqlConn.Close();
 }
 }

As you can see after adding one record program waits for user’s input to provide spouse name. Exclusive lock acquired on “userdata” table is kept held until user provides input and finally the transaction commits.

A simple query as shown below will have to wait until the exclusive lock is released. Until then it is suspended by SQL server.

select * from UserData

Running sp_who2_blocks will output as shown below.

SQL Blocking - sp_who2_blocks

SQL Blocking – sp_who2_blocks

Following command will list the last statement executed in this session.


DBCC INPUTBUFFER(53)

SQL Blocking - List Active Transactions

SQL Blocking – List Active Transactions

Following is the output of “All Blocking Transactions” report.

SQL Blocking - All Blocking Transactions Report

SQL Blocking – All Blocking Transactions Report

There is no “Blocking SQL Statement” in the above output, as there is no statement running in this session. It’s just that locks acquired will not be released until transaction completes.

Permanent Solution

Permanent solution to such a problem is to fix application code. So we need to analyze the trace to identify the business operation and to get an idea of the part of application code causing problem.

Analyzing the Trace

Following columns of various trace events are of utmost importance for us.

  1. Start Time – When exactly a stored procedure, SQL statement or a transaction started.
  2. End Time – When did it complete.
  3. Duration – How long the stored procedure, statement or transaction was running.
  4. TransactionID – ID of the Transaction under which the stored procedure or statement executed.
  5. Object Name – Name of the stored procedure or table.
  6. Text Data – Actual parameters passed to stored procedures or SQL statements.

Getting a list of Top Long Running Transactions

Use the following script:


-- Find Long Running Transactions

SELECT TOP 10 EventClass,
TransactionID,
StartTime,
EndTime,
(Duration/1000000) as Duration_Secs,
TextData,
ObjectName,
SPID,
EventSubClass,
Reads,
Writes,
CPU,
RowCounts
FROM :: fn_trace_gettable('C:\temp\myserver_test_1.trc',1)
Where eventclass = 50 and EventSubClass = 1
order BY duration desc

Transactions are mostly used when saving data. They should be in order of few seconds, like a maximum of 20-30 seconds. If you find transactions with durations in order of minutes or even hours then you should look into the details of that transaction.

Getting a List of Application Calls in Transactions

Use the following script:


SELECT EventClass,
TransactionID,
StartTime,
EndTime,
(Duration/1000000) as Duration_Secs,
TextData,
ObjectName,
SPID,
EventSubClass,
Reads,
Writes,
CPU,
RowCounts
FROM :: fn_trace_gettable('C:\temp\myserver_db_1.trc',1)
Where eventclass IN (50,10,12)
AND TransactionID IN (263653356)

For more details you can include event class 45, SP:StmtCompleted to above query.

Verifing SQL Blocking due to User Interaction in Transaction

Shown below is the output of the trace where the application is getting some input from user in between of a transaction. That input string is then passed to another stored procedure completing the transaction.

Such cases can be identified by comparing the EndTime with the StartTime of two consecutive application calls. Usually there shouldn’t be any gap. If there is some gap then that means that SQL server had to wait for instructions from application.

SQL Blocking - Trace Output

SQL Blocking – Trace Output

Interpreting the Trace Output

4:49:01 PMTransaction Started
4:49:01 PMCouple of stored procedures and SQL statements   completed in sub seconds.
4:49:01 PM to 4:53:43 PMSQL Server waiting for application. Transaction is open.
4:53:43 PMAnother stored procedure executed with parameters   indicating business operation.
4:53:43 PMTransaction Completed

Total Duration of Transaction: 282 Seconds

Time Spent waiting: More than 281 Seconds

About Dinesh Sharma

Experienced system architect, programmer, and trainer. This blog is a way of giving back and helping the community. So feel free to ask a question or to leave a comment.