Attention events can cause open transactions and blocking in SQL Server

Wondering what causes Attention events in a SQL server Profiler trace and how these events can result into severe blocking problems? I will attempt to provide some answers in this post.

First of all let’s talk about what Attentions events are and what may cause them. According to BOL –

“The Attention event class indicates that an attention event, such as cancel, client-interrupt requests, or broken client connections, has occurred. Cancel operations can also be seen as part of implementing data access driver time-outs”

There are three most common reasons of Attention events that I have seen in my experience so far. In each case, Attention events were causing open transactions and resulting in massive blocking issues. Here are those three scenarios -

1. Query Cancellation

User may cancel the currently executing query/batch request at any time – may be the user got tired of waiting on the screen! If the query or the batch was in an explicit user transaction (BEGIN TRAN …. END TRAN), these Attention events could result in open transactions and severe blocking problems. We can reproduce this scenario from within SQL Server Management Studio. Try the following –

Run a SQL Server Profiler trace with the following events selected – Attention, SQL:BatchCompleted, SQL:BatchStarting, SQL:StmtCompleted, SQL:StmtStarting

Open Management Studio and run the following batch –

 USE TEMPDB 
 GO 
 
 IF EXISTS (SELECT * FROM SYS.OBJECTS WHERE OBJECT_ID = OBJECT_ID (N'[DBO].[TEST]') AND TYPE in (N'U')) 
 DROP TABLE [DBO].[TEST] 
 GO 
 
 --Create a Test table and Insert few records in it 
 
 CREATE TABLE TEST (C1 INT, C2 VARCHAR (100)) 
 GO 
 
 INSERT INTO TEST VALUES (1, 'AAA') 
 GO 
 INSERT INTO TEST VALUES (2, 'BBB') 
 GO 
 
 -- Simulate a user transaction that will take a several seconds to execute 
 -- we will use the WAITFOR command to simulate such a transaction 
 
 BEGIN TRAN 
 UPDATE TEST SET C2 = 'MODIFY1' 
 WHERE C1 = 1 
 WAITFOR DELAY '00:00:45' 
 COMMIT TRAN

While the transaction is in progress, click on the Cancel option (red square button on the toolbar) -

You will notice an Attention event in Profiler trace.

In the trace, you will also notice that the COMMIT TRAN statement never executed and so the transaction is still open. You can confirm that by running the following statement from the same query window in which you had cancelled the query

SELECT @@TRANCOUNT 
GO

Now let’s see what kind of locks are being held by this open transaction. Run a select query on the sys.dm_tran_locks DMV (you may want to filter the result on your session to exclude extra noise). You should notice an exclusive (X) lock on the row (RID), and Intent exclusive (IX) locks on the Page and the table. So with those locks in place, if another user starts a query that needs a conflicting lock on any of these resources, you will see blocking. For example, if another user/transaction/query tries to SELECT/UPDATE/DELETE the same row, it will get blocked by the open transaction. Try running this SELECT query in a another query window

SELECT * FROM TEST WHERE C1=1 
GO

Open the “Activity – All Blocking Transactions” server report to analyze the blocking chain (right click on your SQL instance in Object Explorer -> Reports -> Standard Reports -> Activity – All Blocking Transactions)

So the question is how long will this blocking go on for? Actually this blocking chain will go indefinitely until one of the following events occurs –

The open transaction is committed or rolled back manually, since we just saw that SQL server will not automatically commit or rollback the transaction on Attention events.
The connection (or SQL Server session) that started the transaction is terminated. This will happen when the user disconnects from the application.
The connection is recycled in a connection the pool, if the application is using connection pooling.

2. Query Timeouts:

This is the second most common reason I have seen in my experience, which causes Attention events, open transactions and blocking issues. The default query timeout in SQL Server is 0, which means that a query will run indefinitely until completion. However, application developers can change the default query timeout value in SQL Server connection string. Also, OLEDB and ODBC providers of SQL Server have non-zero query timeout values as discussed in this article – DBA’s Quick Guide to Timeouts. Query timeouts, if not handled properly, can cause blocking issues in SQL Server. Let’s see how that can happen -

Open a new query editor window in Management Studio that will prompt you to specify the authentication details. You can do that by clicking on the File menu –> New –> Database Engine Query. On the Connect to Database Engine screen, click on the Option >> button and change the Execution time-out setting from default of 0 to 15. The default value of 0 means the query will run indefinitely. Here is a snapshot-

Restart the Profiler trace and run the following batch from the query window that you just opened –

 USE TEMPDB 
 GO 
 
 -- Run a TSQL batch request that would take a few seconds to execute 
 -- We will use the WAITFOR command to simulate such a query 
 
 IF EXISTS (SELECT * FROM SYS.OBJECTS WHERE OBJECT_ID = OBJECT_ID(N'[DBO].[TEST2]') AND TYPE IN (N'U')) 
 DROP TABLE [DBO].[TEST2] 
 GO 
 
 --Create a Test table and Insert few records in it 
 
 CREATE TABLE TEST2 (C1 INT, C2 VARCHAR (100)) 
 GO 
 
 INSERT INTO TEST2 VALUES (1, 'AAA') 
 GO 
 INSERT INTO TEST2 VALUES (2, 'BBB') 
 GO 
 
 --Start a user transaction that would take about 10 seconds to complete
 
 BEGIN TRAN 
 UPDATE TEST2 SET C2 = 'MODIFY1' 
 WHERE C1 = 1 
 WAITFOR DELAY '00:00:45' 
 COMMIT TRAN

After 15 seconds, which is the query timeout value that we had set while connecting to the server, the batch will terminate with the following timeout error –

Msg -2, Level 11, State 0, Line 0 Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.

You will also notice an Attention event in the trace. If you check the open transaction count by running the SELECT @@TRANCOUNT query from the same query window in which you were running the batch, it will return 1, meaning that there is one open transaction. If you run a SELECT query on the sys.dm_tran_locks DMV, you will notice the same set of locks being held by the open transaction as you saw in the first scenario. If the application is not handling the query timeout errors and rolling back open transactions, it will result in blocking.

What about Lock timeout errors? Will they also result in Attention events?

The answer is NO! Lock Timeout errors do not cause Attention events and execution will proceed to the next statements in the transaction. See it for yourself!

Run the following batch from a new query window (if you are using an existing query window that is already open, make sure to roll back all open transactions in that window) -

 USE TEMPDB 
 GO 
 
 -- Create a Test table and Insert some rows in it 
 IF EXISTS (SELECT * FROM SYS.OBJECTS WHERE OBJECT_ID = OBJECT_ID(N'[DBO].[TEST3]') AND TYPE IN (N'U')) 
 DROP TABLE [DBO].[TEST3] 
 GO 
 
 CREATE TABLE TEST3 (C1 INT, C2 VARCHAR (100)) 
 GO 
 
 INSERT INTO TEST3 VALUES (1, 'AAA') 
 GO 
 
 INSERT INTO TEST3 VALUES (2, 'BBB') 
 GO 
 
 -- Run a TSQL batch request that will start a 
 -- transaction but do not COMMIT or ROLLBACK the transaction 
 -- I am doing this to create a classic blocking 
 -- scenario to test lock timeout errors 
 
 BEGIN TRAN 
 UPDATE TEST3 SET C2 = 'MODIFY1' 
 WHERE C1 = 1 
 GO

Restart the Profiler trace and run the following batch in a second query editor window –

USE Tempdb
 GO
 
 SET LOCK_TIMEOUT 5000 
 GO 
 
 BEGIN TRAN 
 UPDATE TEST3 SET C2 = 'MODIFYAGAIN' 
 WHERE C1 = 1 
 COMMIT TRAN

Expectedly, after 5 seconds, the batch will terminate with a lock timeout error (Error 1222) –

Msg 1222, Level 16, State 45, Line 3 Lock request time out period exceeded. The statement has been terminated.

However, you will not see an Attention event in the Profiler trace this time. You will also notice that after the lock timeout error occurred, SQL server continued with the execution of the batch and finally committed the transaction even though the UPDATE statement had failed. If you run a SELECT @@TRANCOUNT in the same query window, it will return 0, meaning there is no open transaction

3. Applications not processing the result set completely

I have seen this problem while working with a customer who had an ODBC application fetching data from SQL Server. The application was coded to ask for a result set in a cursor, fetch the first few records (and not all of the requested rows) and discard the rest. This problem has been described in detail in this blog. Unfortunately, I don’t have an application to demonstrate this behavior. But if you are noticing the following characteristics with your application and seeing a large number of Attention events and blocking chains in SQL Server, this could be the case.

You notice a large number of Attention events in the a SQL Server profiler trace and you have confirmed that they are not caused by user cancellation or query timeouts
You are seeing a pattern in the trace showing that the Attention event arrived right after the batch started, generally milliseconds afterwards and not something like a 30 second query timeout. Here is a snapshot of this pattern that I was seeing in SQL traces –

You are seeing ASYNC_NETWORK_IO waits in SQL Server, which is an indication that the application is not processing the result set completely.

Solutions:

So now that we know how Attention events can result in open transactions and blocking problems, what can we do to resolve this problem? Here are two solutions that I have successfully tried while working with customers –

Check after each transaction (or before starting a new transaction in the same session) to see if the transaction is complete by using the following statement:

IF @@TRANCOUNT > 0 ROLLBACK

Use SET XACT_ABORT ON for the connection, or in any stored procedures which begin transactions and are not cleaning up following an error. In the event of a run-time error, this setting will abort any open transactions and return control to the client. Note that T-SQL statements following the statement which caused the error will not be executed. It’s a good practice to set XACT_ABORT to on before starting any user transactions so that any batch terminating error (such as Attention events) would roll back the entire transaction. If you can’t modify the application easily to specify XACT_ABORT, you can try the USER_OPTIONS configuration setting in SQL Server to turn on XACT_ABORT on an entire instance of SQL Server. The below snapshot shows how to turn on XACT_ABORT on an instance of SQL Server –

Important: This (or setting it at the connection level) does not guarantee desired behavior in case of an Attention event though, since application code can override the setting. The only completely reliable way would be to set XACT_ABORT to ON before every BEGIN TRAN

SOURCE: https://blogs.msdn.microsoft.com

Hunting down the origins of FETCH API_CURSOR and sp_cursorfetch

So picture the following scenario on a SQL Server 2008 R2 instance (an amalgam of various DBA situations you've no doubt seen before)…

You get a call from the application team reporting slow performance on a specific service. They don’t know why it is slow but they do know the session that is running too slow based on the connection and session properties. They tell you that the issue is happening right now and that they are seeing the offending session issue the following RPC:Completed events in SQL Profiler:

· exec sp_cursorfetch 180150003,32,1,1

They ask you to take it over and find out what is happening. You’re not sure what the original query is or why this is showing up, but you see the session id they are pointing to is “53” (and you don’t remember the syntax around pulling SQL text “the new way” – so you execute the following ):

DBCC INPUTBUFFER (53)

This returns:

FETCH API_CURSOR0000000000000004

You do a few quick searches and it seems to have a relationship with server-side cursors.

You try activity monitor – just in case – but again, no luck:

You take out the new DMV queries – but your query against sys.dm_exec_requests isn’t turning up anything for session id 53 because the executions of this cursor are erratic and you're not timing it (but SQL Profiler does show it plodding along in fits and starts).

You then run the following query against sys.dm_exec_connections and see if that turns up anything useful based on the most recent SQL handle:

SELECT t.text

FROM sys.dm_exec_connections c

CROSS APPLY sys.dm_exec_sql_text (c.most_recent_sql_handle) t

WHERE session_id = 53

This returns:

FETCH API_CURSOR0000000000000004

Didn’t help.

So what about other DMVs? You eventually find a reference to the sys.dm_exec_cursors DMV and see it can tell you about open cursors, their properties and associated SQL handle. But you're not sure the SQL Handle will be any help because it hasn't been helpful with the other DMVs:

SELECT c.session_id, c.properties, c.creation_time, c.is_open, t.text

FROM sys.dm_exec_cursors (53) c

CROSS APPLY sys.dm_exec_sql_text (c.sql_handle) t

What do we get this time? Something a bit more useful:

From the results we see the properties of the cursor (using scroll locks) and we also see when it was created – and we see the original query text (unlike the cryptic FETCH API_CURSOR business or the sp_cursorfetch). We see it was a SELECT * FROM dbo.FactResellerSales.

Now this isn’t to say that SQL Profiler wouldn’t have helped in this situation – but in this case the cursor was defined before the developers captured the downstream activity.

If they had been tracing it sooner, you might have seen something like this (and then see it followed by sp_cursorfetch):

declare @p1 int

set @p1=180150003

declare @p3 int

set @p3=2

declare @p4 int

set @p4=2

declare @p5 int

set @p5=-1

exec sp_cursoropen @p1 output,N'SELECT * FROM dbo.FactResellerSales',@p3 output,@p4 output,@p5 output

select @p1, @p3, @p4, @p5

But in a situation where you’re reacting to an incident (fox has already left the henhouse, so to speak), chances are you weren’t tracing this activity. And if that’s the case, you’ve now found one reason to use sys.dm_exec_cursors if you didn’t already have one.

SOURCE: http://www.sqlskills.com

Silveirinha World

quarta-feira, 23 de março de 2016