Hello everybody!
The theme of today's post is timeout, which consists of a timeout (usually measured in seconds) in which an operation will wait until it forcibly terminates execution, if this timeout is reached.
The purpose of this post is to show how to identify timeout or broken connections using Extended Events (XE) or SQL Profiler (Trace) and facilitate the analysis of this type of problem that is so common in everyday life.
After identifying the root cause of the timeout, the solution to solve this is to try to optimize the queries through Performance Tuning techniques to make the execution time be reduced. Depending on the process, if it really is something that involves a lot of processing and it really takes time, it's worth increasing the timeout time for that particular process, but that's a subject for my series of Performance Tuning in SQL Server.
In SQL Server, we have several types of timeouts, which I would like to highlight:
- Remote Query Timeout (sp_configure), which defines the maximum time that remote queries (using linked server) can run (default time: 600 seconds)
- lock_timeout (SET command), which is the time that the client executing a SQL command will wait for a lock to be released to continue executing that command (default time: -1 = infinity = will wait indefinitely)
- Command Timeout is a property of database connection drivers, such as ADO.NET, JDBC and others, that allows you to set a maximum time limit that an SQL statement can execute against the database. This value can be dynamically changed in the application and can have different timeouts depending on the context. (default time: 30 seconds)
- Connection Timeout is a property of connection string which allows you to set a maximum time limit the connection driver will wait to establish a connection to the database (default time: 30 seconds)
It is very important to make clear that the lock_timeout, Command Timeout and Connection Timeout timeouts they are limits imposed by the client/connection driver and not the database.
When a timeout occurs, it will generate an exception in the application, but from the database point of view, there was no error or problem in the execution (or connection), precisely because the timeout does not occur in the database, that is, it is not the bank that is interrupting the SQL statement, but the application.
If you want to know more about SQL Server SET commands, go to the article SQL Server SET Commands.
I also recommend reading my article Timeout when running Queries via Linked Server on SQL Server, if you are experiencing any problem related to this.
Also, let's not forget the timeout of the development tool (IDE) that the DBA or developer uses to access the database.
SQL Server Management Studio (SSMS), for example, has a property called “Execution time-out”, which defines how long SSMS should wait to execute a query (internally this is the Command Timeout property of the connection driver).
The default value of this property in SSMS is 0 (infinite), that is, it has no time limit.
How to generate a timeout using SQLCMD
In order to be able to create some test logs and demonstrate how to identify timeouts in the database, I will force timeouts to occur in the database.
For this, I will use the SQLCMD utility and the property -t 1 (query timeout of 1 second), and I will use the command WAITFOR DELAY '00:00:05′, which waits for 5 seconds, that is, whenever I execute this command, I will generate an event timeout.
Execution Result:
Generated timeouts.
How to identify database timeouts using Extended Events (XE)
To identify timeouts in the database, I've seen many people use the query execution time to define whether there was a timeout or not. As the default is 30 seconds, one assumes that if the query took exactly 30 seconds, it is because a timeout occurred. However, this is not always true, because, as I mentioned at the beginning of the post, for each context or screen of the system, the developer can define different timeout times.
One of the ways to be able to identify whether a timeout really occurred is using Extended Events (XE), analyzing the attention event class, available since SQL Server 2012, which indicates that an event that requires attention has occurred, such as cancellations, client interrupt requests, and lost client connections. Cancel operations can also be seen as part of implementing driver data access timeouts (timeouts)
I'll share the script ready to implement the monitoring and also prints of the Extended Events interface, in case you want to create it yourself, via screen.
Script to monitor SQL Server timeout using Extended Events (XE)
| 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 | -- Apaga a sessão, caso ela já exista IF ((SELECT COUNT(*) FROM sys.server_event_sessions WHERE [name] = 'Monitora Timeouts') > 0) DROP EVENT SESSION [Monitora Timeouts] ON SERVER GO CREATE EVENT SESSION [Monitora Timeouts] ON SERVER ADD EVENT sqlserver.attention ( ACTION ( sqlserver.client_app_name, sqlserver.client_hostname, sqlserver.[database_name], sqlserver.nt_username, sqlserver.num_response_rows, sqlserver.server_instance_name, sqlserver.server_principal_name, sqlserver.server_principal_sid, sqlserver.session_id, sqlserver.session_nt_username, sqlserver.session_server_principal_name, sqlserver.sql_text, sqlserver.username ) ) ADD TARGET package0.event_file ( SET filename = N'D:\SQL\Traces\Monitora_Timeout.xel', -- Não esqueça de mudar o caminho aqui :) max_file_size = ( 50 ), -- Tamanho máximo (MB) de cada arquivo max_rollover_files = ( 8 ) -- Quantidade de arquivos gerados ) WITH ( STARTUP_STATE = OFF ) -- Ativando a sessão (por padrão, ela é criada desativada) ALTER EVENT SESSION [Monitora Timeouts] ON SERVER STATE = START GO |
Interface to monitor timeout in SQL Server using Extended Events (XE)
Click to view screenshots
Screenshot 1 – Open XE Wizard from SSMS Object Explorer
Screenshot 2 – Home screen
Screenshot 3 – Define the Extended Event name and check the checkbox to enable the event at the end of the configuration
Screenshot 4 – Marking that I don't want to use any template
Screenshot 5 – Select the “attention” event and add it to the list of selected events
Screenshot 6 – Confirm selection and proceed to next screen
Screenshot 7 – Selecting the return fields you want the event to return
Screenshot 8 – Moving forward without applying filters
Screenshot 9 – Define the location to save the .xel file, maximum size and rollover of files
Screenshot 10 – Final screen and operations summary
Script to read data written by Extended Event (XE)
Click to view the script
| 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 | IF (OBJECT_ID('dbo.Historico_Timeout') IS NULL) BEGIN -- DROP TABLE dbo.Historico_Timeout CREATE TABLE dbo.Historico_Timeout ( [Dt_Evento] DATETIME, [session_id] INT, [duration] BIGINT, [server_instance_name] VARCHAR(100), [database_name] VARCHAR(100), [session_nt_username] VARCHAR(100), [nt_username] VARCHAR(100), [client_hostname] VARCHAR(100), [client_app_name] VARCHAR(100), [num_response_rows] INT, [sql_text] XML ) WITH(DATA_COMPRESSION=PAGE) END DECLARE @TimeZone INT = DATEDIFF(HOUR, GETUTCDATE(), GETDATE()) DECLARE @Dt_Ultimo_Evento DATETIME = ISNULL((SELECT MAX(Dt_Evento) FROM dbo.Historico_Timeout WITH(NOLOCK)), '1990-01-01') IF (OBJECT_ID('tempdb..#Eventos') IS NOT NULL) DROP TABLE #Eventos ;WITH CTE AS ( SELECT CONVERT(XML, event_data) AS event_data FROM sys.fn_xe_file_target_read_file(N'D:\SQL\Traces\Monitora_Timeout*.xel', NULL, NULL, NULL) ) SELECT DATEADD(HOUR, @TimeZone, CTE.event_data.value('(//event/@timestamp)[1]', 'datetime')) AS Dt_Evento, CTE.event_data INTO #Eventos FROM CTE WHERE DATEADD(HOUR, @TimeZone, CTE.event_data.value('(//event/@timestamp)[1]', 'datetime')) > @Dt_Ultimo_Evento INSERT INTO dbo.Historico_Timeout SELECT A.Dt_Evento, xed.event_data.value('(action[@name="session_id"]/value)[1]', 'int') AS [session_id], xed.event_data.value('(data[@name="duration"]/value)[1]', 'bigint') AS [duration], xed.event_data.value('(action[@name="server_instance_name"]/value)[1]', 'varchar(100)') AS [server_instance_name], xed.event_data.value('(action[@name="database_name"]/value)[1]', 'varchar(100)') AS [database_name], xed.event_data.value('(action[@name="session_nt_username"]/value)[1]', 'varchar(100)') AS [session_nt_username], xed.event_data.value('(action[@name="nt_username"]/value)[1]', 'varchar(100)') AS [nt_username], xed.event_data.value('(action[@name="client_hostname"]/value)[1]', 'varchar(100)') AS [client_hostname], xed.event_data.value('(action[@name="client_app_name"]/value)[1]', 'varchar(100)') AS [client_app_name], xed.event_data.value('(action[@name="num_response_rows"]/value)[1]', 'int') AS [num_response_rows], TRY_CAST(xed.event_data.value('(action[@name="sql_text"]/value)[1]', 'varchar(max)') AS XML) AS [sql_text] FROM #Eventos A CROSS APPLY A.event_data.nodes('//event') AS xed (event_data) |
Example of returned data:
- SQL Server - How to identify deprecated features being used in the instance (Extended Events - XE)
- SQL Server - How to generate a deadlock history for failure analysis in routines
- SQL Server - How to Create Error and Exception Tracking in Your Database Using Extended Events (XE)
- SQL Server - How to identify and collect time consuming query information using Extended Events (XE)
How to identify database timeouts using SQL Profiler (Trace)
Another way to identify timeouts in the database is to use SQL Profiler (Trace), especially if you are using a version prior to 2012, which does not support the Extended Events attention event.
To achieve this goal with SQL Profiler, we will monitor the RPC:Completed, SP:StmtCompleted, and SQL:BatchCompleted events and filter only the results that meet the Error = 2 filter.
Even applying this filter, you should closely monitor if your server's workload will increase a lot after activating this trace, because everything that is executed will be analyzed by this trace.
Whenever possible, try to use Extended Events (XE) instead of Profiler (Trace), especially for this situation.
Script to monitor timeout on SQL Server using SQL Profiler (Trace)
| 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 | -------------------------------------------------------- -- Armazena os resultados do Trace na tabela -------------------------------------------------------- DECLARE @Trace_Id INT, @Path VARCHAR(MAX) SELECT @Trace_Id = id, @Path = [path] FROM sys.traces WHERE [path] LIKE '%Monitora_Timeout.trc' IF (@Trace_Id IS NOT NULL) BEGIN -- Interrompe o rastreamento especificado. EXEC sys.sp_trace_setstatus @Trace_Id = @Trace_Id, @status = 0 -- Fecha o rastreamento especificado e exclui sua definição do servidor. EXEC sys.sp_trace_setstatus @Trace_Id = @Trace_Id, @status = 2 IF (OBJECT_ID('dbo.Historico_Timeout') IS NULL) BEGIN -- DROP TABLE dbo.Historico_Timeout CREATE TABLE [dbo].[Historico_Timeout] ( [TextData] VARCHAR(MAX), [NTUserName] NVARCHAR(256), [HostName] NVARCHAR(256), [ApplicationName] NVARCHAR(256), [LoginName] NVARCHAR(256), [Duration] DECIMAL(15, 2), [StartTime] DATETIME, [EndTime] DATETIME, [ServerName] NVARCHAR(256), [DatabaseName] NVARCHAR(256) ) WITH ( DATA_COMPRESSION = PAGE ) CREATE CLUSTERED INDEX [SK01_Traces] ON [dbo].[Historico_Timeout] ([StartTime]) WITH (FILLFACTOR=80, STATISTICS_NORECOMPUTE=ON, DATA_COMPRESSION = PAGE) END INSERT INTO dbo.Historico_Timeout ( TextData, NTUserName, HostName, ApplicationName, LoginName, Duration, StartTime, EndTime, ServerName, DatabaseName ) SELECT TextData, NTUserName, HostName, ApplicationName, LoginName, CAST(Duration / 1000 / 1000.00 AS NUMERIC(15, 2)) Duration, StartTime, DATEADD(MILLISECOND, Duration / 1000, StartTime) AS EndTime, ServerName, DatabaseName FROM ::fn_trace_gettable(@Path, DEFAULT) WHERE ApplicationName NOT LIKE '%Management Studio%' AND Error = 2 -- Abort ORDER BY StartTime -------------------------------------------------------- -- Apaga o arquivo de trace -------------------------------------------------------- DECLARE @Fl_Xp_CmdShell_Ativado BIT = (SELECT (CASE WHEN CAST([value] AS VARCHAR(MAX)) = '1' THEN 1 ELSE 0 END) FROM sys.configurations WHERE [name] = 'xp_cmdshell') IF (@Fl_Xp_CmdShell_Ativado = 0) BEGIN EXECUTE sp_configure 'show advanced options', 1; RECONFIGURE WITH OVERRIDE; EXEC sp_configure 'xp_cmdshell', 1; RECONFIGURE WITH OVERRIDE; END DECLARE @Cmd VARCHAR(4000) = 'del ' + @Path + ' /Q' EXEC sys.xp_cmdshell @Cmd IF (@Fl_Xp_CmdShell_Ativado = 0) BEGIN EXEC sp_configure 'xp_cmdshell', 0; RECONFIGURE WITH OVERRIDE; EXECUTE sp_configure 'show advanced options', 0; RECONFIGURE WITH OVERRIDE; END END -------------------------------------------------------- -- Ativa o trace novamenmte -------------------------------------------------------- DECLARE @rc INT, @TraceID INT, @maxfilesize BIGINT = 50, @on BIT = 1 EXEC @rc = sp_trace_create @TraceID OUTPUT, 0, N'D:\SQL\Traces\Monitora_Timeout', @maxfilesize, NULL IF (@rc = 0) BEGIN exec sp_trace_setevent @TraceID, 10, 1, @on exec sp_trace_setevent @TraceID, 10, 10, @on exec sp_trace_setevent @TraceID, 10, 3, @on exec sp_trace_setevent @TraceID, 10, 6, @on exec sp_trace_setevent @TraceID, 10, 8, @on exec sp_trace_setevent @TraceID, 10, 11, @on exec sp_trace_setevent @TraceID, 10, 12, @on exec sp_trace_setevent @TraceID, 10, 13, @on exec sp_trace_setevent @TraceID, 10, 14, @on exec sp_trace_setevent @TraceID, 10, 31, @on exec sp_trace_setevent @TraceID, 10, 34, @on exec sp_trace_setevent @TraceID, 10, 35, @on exec sp_trace_setevent @TraceID, 10, 60, @on exec sp_trace_setevent @TraceID, 45, 1, @on exec sp_trace_setevent @TraceID, 45, 3, @on exec sp_trace_setevent @TraceID, 45, 6, @on exec sp_trace_setevent @TraceID, 45, 8, @on exec sp_trace_setevent @TraceID, 45, 10, @on exec sp_trace_setevent @TraceID, 45, 11, @on exec sp_trace_setevent @TraceID, 45, 12, @on exec sp_trace_setevent @TraceID, 45, 13, @on exec sp_trace_setevent @TraceID, 45, 14, @on exec sp_trace_setevent @TraceID, 45, 28, @on exec sp_trace_setevent @TraceID, 45, 34, @on exec sp_trace_setevent @TraceID, 45, 35, @on exec sp_trace_setevent @TraceID, 45, 60, @on exec sp_trace_setevent @TraceID, 12, 1, @on exec sp_trace_setevent @TraceID, 12, 3, @on exec sp_trace_setevent @TraceID, 12, 11, @on exec sp_trace_setevent @TraceID, 12, 6, @on exec sp_trace_setevent @TraceID, 12, 8, @on exec sp_trace_setevent @TraceID, 12, 10, @on exec sp_trace_setevent @TraceID, 12, 12, @on exec sp_trace_setevent @TraceID, 12, 13, @on exec sp_trace_setevent @TraceID, 12, 14, @on exec sp_trace_setevent @TraceID, 12, 31, @on exec sp_trace_setevent @TraceID, 12, 35, @on exec sp_trace_setevent @TraceID, 12, 60, @on -- Inclui os filtros declare @intfilter int declare @bigintfilter bigint set @intfilter = 2 exec sp_trace_setfilter @TraceID, 31, 0, 0, @intfilter set @intfilter = NULL exec sp_trace_setfilter @TraceID, 31, 0, 1, @intfilter -- Ativa o trace exec sp_trace_setstatus @TraceID, 1 END |
Interface to monitor timeout in SQL Server using SQL Profiler (Trace)
Click to view screenshots
Screenshot 1 – Opening SQL Profiler
Screenshot 2 – Connecting to database
Screenshot 3 – Select the Tuning template and click on the “Event Selection” tab
Screenshot 4 – Check the “Show all columns” checkbox, check the “Error” column (and the others you want to return) and click the “Column Filters” button
Screenshot 5 – Apply a filter on the Error column and use the measure Error = 2. Check the checkbox “Exclude rows that do not contain values”
Screenshot 6 – Click the Run button to start the trace on the server
Screenshot 7 – Analyze the results found
Screenshot 8 – Results collected and already stored in a history table
- SQL Server - How to identify and collect time consuming query information using Trace (SQL Server Profiler)
- SQL Server - How to audit permission errors on objects using SQL Profiler (Trace)
- Using SQL Server Standard Trace to Audit Events (fn_trace_gettable)
- Monitoring DDL and DCL Operations Using SQL Server fn_trace_gettable
Excerpt from a live where the Marcio Junior demonstrates how to identify timeout in SQL Server
And that's it folks!
A big hug and even more.
