Identifying client timeouts

Long running queries often causes client timeout in our applications. One good solution to attack this problem is to identify the timeouts and optimize the queries causing the timeouts.

Client timeouts or connection interruptions are identified as Attention events. We can capture the attention events using an Extended Events session.

The script to create the XE session will be the following:

CREATE EVENT SESSION [timeout] ON SERVER
ADD EVENT sqlserver.attention(
    ACTION(sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,
      sqlserver.database_name,sqlserver.is_system,sqlserver.nt_username,sqlserver.server_principal_name,
      sqlserver.sql_text,sqlserver.username))
ADD TARGET package0.event_file(SET filename=N'C:\xel\timeout.xel')
GO

You need to customize the path for the XE files in the filename attribute of the target.

After activating the session and let it running, we need to query the information from the XE session. This kind of query uses a lot of XML, so the best solution is to create a function to turn this query easier.

The script for the function will be this:

CREATE FUNCTION [dbo].[ReadClientTimeout]
(
      -- Add the parameters for the function here
      @xel varchar(500),
      @xem varchar(500)
)
RETURNS TABLE
AS
RETURN
(
with qry as (
select
theNodes.event_data.value('(action[@name="database_name"]/value)[1]','varchar(50)')
           as database_name,
theNodes.event_data.value('(action[@name="client_hostname"]/value)[1]','varchar(50)')
           as client_hostname,
theNodes.event_data.value('(action[@name="client_app_name"]/value)[1]','varchar(50)')
           as client_app_name,
theNodes.event_data.value('(data[@name="duration"]/value)[1]','bigint') as duration,
theNodes.event_data.value('(action[@name="sql_text"]/value)[1]','varchar(4000)') as sql_text,
theNodes.event_data.value('(action[@name="user_name"]/value)[1]','varchar(50)') as user_name,
theNodes.event_data.value('(action[@name="is_system"]/value)[1]','varchar(50)') as is_system,
theNodes.event_data.value('(action[@name="nt_user_name"]/value)[1]','varchar(50)')
           as nt_user_name,
theNodes.event_data.value('(action[@name="server_principal_name"]/value)[1]','varchar(50)')
           as server_principal_name
from
      (select convert(xml,event_data) event_data
            from
       sys.fn_xe_file_target_read_file(@xel, @xem, NULL, NULL)) as theData
cross apply theData.event_data.nodes('//event') theNodes(event_data)
       )
select database_name,client_hostname,client_app_name,
            duration,sql_text,user_name,is_system,
            nt_user_name,server_principal_name
             from qry
 )
GO

We need to test and see our new session capturing a timeout. In SSMS, go to File->New -> Database Engine Query.

In the “Connect to database engine” window, click in Options->Connection Properties and change the value of “Execution timeout” to 5 seconds. Fill the information in the Connection tab and click ok to open a new query window with five seconds as execution timeout.

Now you will receive a timeout each time you run the following instruction:

waitfor delay '00:00:06'

We need to query the function to see the information captured about the timeout:

select * from dbo.readclienttimeout('C:\xel\timeout*.xel',null)

We can use client_app_name, database_name and other fields to identify the timeout events. Notice that sql_text contains the query that caused the timeout and needs to be optimized.