Easy Monitoring: Application Timeouts in SQL Server with XEvents

One of my least favorite feelings in the IT world is to be caught by surprise. Not just any type of surprise. I am talking about the kind of surprise that comes from an end user letting me know that the Database is broken. Afterall, the monitoring and efforts I put into place should let me know when there is a truly broken database. It’s almost like the nightmare of getting to work and discovering you are not properly dressed for the day – though you thought you were appropriately dressed.

Many times the alarm from an end-user is not entirely accurate or  maybe it isn’t truly broken but they don’t know how to communicate it any other way. Then there are the times when it is legitimately broken but none of the monitoring solutions caught wind of the system being broken. One such way that the application gets “broken” for the end user and finds a way of bypassing all of the implemented monitoring solutions is when the “break” is due to an application timeout.

Application Timeouts are the Devil…

If there is a timeout that occurs, shouldn’t SQL Server know the details of the timeout? Well, that is a complex assertion. You see, an application timeout is not a SQL Server timeout so not everything is passed up to SQL Server that you might expect to see. Despite this lack of detail, we do have the ability to trap these types of errors within SQL Server.

How are we able to see anything with these types of errors? The application timeout is exposed to us via the Attention Event Class. The Attention Event Class lets us know when there is an “attention event” – yeah super descriptive right? An attention event is basically a signal to SQL Server that there was a cancel request, broken connection, client side interrupt request (e.g. somebody hit the stop button in SSMS) , bored application that gave up because it was waiting too long (like an impatient child).

If you look at the documentation for the Attention Event Class, there is quite a bit of data exposed. There is a bit of a trick to that however. To expose the trick, we first need to know how we will be using the Attention Event Class to get at this unwanted application timeouts. As the name implies, we will be looking for an “event” and what better tool than Extended Events (XEvents) to get at the internals of these types of errors and events?

Given the name of the class and a hint that we will be using XEvents, we need to know the name of the event to look at – or do we? That clue is also given in the name of the class – “Attention”.

Event Classes and XEvents

Now that we have the basics that are required for us to go out and start building an XEvent Session using the “Attention” event, we need to finish exposing the little trick. Let’s take a look at the payload returned by the event.

DECLARE @EventName VARCHAR(64) = 'attention' 
,@ReadFlag VARCHAR(64) = 'readonly' --readonly' --ALL if all columntypes are desired
 
SELECT oc.OBJECT_NAME AS EventName
,oc.name AS column_name, oc.type_name
,oc.column_type AS column_type
,oc.column_value AS column_value
,oc.description AS column_description
,ca.map_value AS SearchKeyword
FROM sys.dm_xe_object_columns oc
CROSS APPLY (SELECT TOP 1 mv.map_value
FROM sys.dm_xe_object_columns occ
INNER JOIN sys.dm_xe_map_values mv
ON occ.type_name = mv.name
AND occ.column_value = mv.map_key
WHERE occ.name = 'KEYWORD'
AND occ.object_name = oc.object_name) ca
WHERE oc.object_name = @EventName
AND oc.column_type <> @ReadFlag
;
/* map values for the dop_statement_type
what is the data that would be returned to me ? */SELECT oc.object_name as EventName,oc.name as ColName,mv.name as MapName, map_key, map_value 
FROM sys.dm_xe_map_values mv
Inner Join sys.dm_xe_object_columns oc
on mv.name = oc.type_name
AND mv.object_package_guid = oc.object_package_guid
WHERE oc.object_name = @EventName
AND oc.column_type <> @ReadFlag
ORDER BY MapName, mv.map_key;
GO

Executing that query to discover the payload, I see the following:

According to XEvents, the entire payload for this event is all of 2 data points. This clearly is a contradiction to the documentation, right? No, not necessarily. A closer look at the payload in the documentation illustrates that a lot of the payload shown there is actually data that is retrieved by attaching actions to the event that is triggered. While there are many actions associated with the “Attention Event Class”, I will not be using all of those actions. I am just looking for a good set of data rather than an exhaustive set of data related to this timeout issues.

Building a Session

The hard stuff is now out of the way. All that is left to do is put together an XEvent session so we can start monitoring those pesky timeouts. This is now where the XEasy button comes into play. The following is the session script for use when contending with these pesky timeouts.

-- Create the Event Session
IF EXISTS ( SELECT *
FROM sys.server_event_sessions
WHERE name = 'AppQueryTimeout' )
DROP EVENT SESSION AppQueryTimeout 
    ON SERVER;
GO
EXECUTE xp_create_subdir 'C:DatabaseXE';
GO
CREATE EVENT SESSION AppQueryTimeout
ON SERVER
    ADD EVENT sqlserver.attention
    (ACTION
     (
         sqlserver.session_id
       , sqlserver.database_id
       , sqlserver.database_name
       , sqlserver.username
       , sqlserver.nt_username
       , sqlserver.sql_text
       , sqlserver.client_hostname
       , sqlserver.client_app_name
       , package0.event_sequence
       , sqlserver.context_info
       , sqlserver.client_connection_id
       , sqlserver.tsql_stack
       , sqlserver.tsql_frame
     )
     WHERE ([is_system] = 0)
AND [sqlserver].[client_app_name]<>'Microsoft SQL Server Management Studio - Transact-SQL IntelliSense'
    )
    ADD TARGET package0.event_file
    (SET filename = N'C:DatabaseXEAppQueryTimeout', max_file_size = (5), max_rollover_files = (2))
    WITH (MAX_DISPATCH_LATENCY = 10 SECONDS
, TRACK_CAUSALITY = ON
, STARTUP_STATE = ON);
ALTER EVENT SESSION AppQueryTimeout ON SERVER STATE = START;

Results…

With this session running, when an application timeout occurs, or a query is cancelled for some reason outside of the DB Engine, an attention event will be captured. This will look something like the following:

If you are uncertain if the session is working, trying running some bulk loads from a .Net application. Certain versions of .Net will trigger this event due to a change in how the connection is closed. Some versions will use the cancel method to close the connection which triggers an attention event.

Put a bow on it

Application timeouts can be surprising little problems causing premature grey hairs. Never fear, this article with the XEvents session, that I shared, are the perfect solution. This article presents an easy button of sorts with a pre-made XEvent Session script to help you capture these pesky gremlins.

Are you interested in learning more about Extended Events? Here is a large library of articles: Check these out!

Want to learn interesting info about your indexes? Try this index maintenance article or this index size article.

This is the eighth article in the 2020 “12 Days of Christmas” series. For the full list of articles, please visit this page.

The post Easy Monitoring: Application Timeouts in SQL Server with XEvents first appeared on SQL RNNR.