Solving a SQL Server Timeout Mystery
I was tasked with investigating intermittent timeouts in a software product.
We talked to the customer and their tech lead. Here is what they told us.
They had two servers: one running the VoIP application and another running SQL Server. After every call, the VoIP server saved the call data to the database. Every now and then, the save operation timed out.
The two servers were in different time zones, three hours apart.
“Have you checked how long the queries take to execute?”
“We have. A typical stored procedure finishes in a fraction of a second. During peak hours, the write queue can reach 100 threads, and the procedure still finishes in about a second. The timeout is set to 30 seconds.”
I didn’t get SQL Server access immediately, but I soon received a VPN connection and credentials for the customer’s computer.
My first step was to launch Performance Monitor (perfmon) and configure a Data Collector Set to log CPU, memory, disk, and network activity every five seconds.
It’s a standard Windows tool. Just press Win+R and type “perfmon”.
Setting Up Performance Monitor
To configure a Data Collector Set, go to Data Collector Sets, create a new set, and select Create manually (Advanced).
Select Performance counter, choose the sampling interval, and add the counters you want to monitor. I used a five-second interval and selected the following counters:
- Processor → % Processor Time
- Physical Disk → % Disk Time
- Physical Disk → Avg. Disk Queue Length
- Physical Disk → Current Disk Queue Length
- Memory → Available MBytes
- Network Adapter → Bytes Total/sec
- Network Adapter → Output Queue Length
Click OK and choose where to save the collected data. By default, Windows may use a location on the C: drive. I’d recommend choosing another drive with at least 10 GB of free space.
Select your new Data Collector Set and click Start. That’s it.
After stopping the collector, you can view the results under Reports → User Defined → [Your Collector Set Name].
I started the collector, checked how much data it produced in five minutes, estimated the storage requirements for a full day, checked the available disk space, and left it running.
The next morning, I found timeout alerts in my inbox.
I also found a great website: World Time Buddy.
Need to figure out what 12:37 PM in GMT-5 means in Kyiv during winter? This is the place to go.
I converted the timestamps, correlated the timeout alerts with the performance logs, and discovered something interesting: the failures weren’t happening during peak hours. In fact, the server was barely loaded when they occurred.
Windows Event Viewer didn’t reveal anything either. No backups, no errors, no obvious background activity around those timestamps.
So much for the obvious explanations.
Looking at the Timeout Stack
I examined the exception stack:
Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
The statement has been terminated. at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
at System.Data.SqlClient.SqlDataReader.get_MetaData()
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteScalar()
at ProductName.VoIP.DataTier.Execute(String query, CommandType qtype, DataReturnTypes rtnType, Parameter[] parms, Object transaction)
at ProductName.VoIP.BusinessObject.SetCall(Event objEvent, Boolean clientID)
at ProductName.VoIP.EDS.SaveEvent()I found that only two stored procedures were involved. It looked increasingly likely that one of them occasionally failed to finish within the 30-second timeout.
By then, I had finally received access to SQL Server.
The application processed approximately 40,000 calls per day, with around four timeouts during that period. Catching one of these failures manually was practically impossible.
One important detail: this exception was raised on the client side, not directly by SQL Server. A client-side timeout can cancel the running request, but it doesn’t necessarily mean the entire server-side transaction is automatically rolled back. The actual outcome depends on the transaction and error-handling logic.
To investigate further, I used SQL Server Profiler to capture the relevant activity and looked for Attention events.
When a timeout occurred, an Attention event appeared close to the corresponding query in the trace. That made the failed request much easier to find among all the other events.
For background on these events, see Microsoft’s article, [Attention Events Causing Open Transaction and Blocking].
Tracking Down the Timeout
Today, I’d start with Extended Events. It’s generally the better choice for collecting diagnostic information from SQL Server, and you can configure a session to capture exactly the events and data you need.
SQL Server Profiler, on the other hand, is a legacy tool. It can be resource-intensive, especially when capturing large amounts of data on a busy production server, so I wouldn’t make it my first choice for diagnosing performance issues.
Get Oleksandr Shevchenko’s stories in your inbox
Join Medium for free to get updates from this writer.
However, when simpler approaches fail to reveal the cause, a carefully configured Extended Events session-or, if necessary, an old-school SQL Profiler trace-can still be a lifesaver.
In this case, the Attention event was particularly useful. It indicated that the client had canceled a request, helping me correlate the timeout reports with the actual queries involved.
Keep in mind that an Attention event doesn’t necessarily mean a timeout: a query can also be canceled explicitly by a user or application. It identifies the cancellation, not its cause.
Eventually, I captured the query and its parameters:
EXEC xxx_sp_Calls
@param1 = '2015–11–11 15:05:16.542',
…Its execution time was 30,002 milliseconds.
I tried running it in SQL Server Management Studio. It finished almost instantly.
I looked inside the stored procedure. Nothing particularly unusual: an INSERT and a couple of SELECT statements.
I’d seen this kind of behavior before, but I decided to do some reading anyway. I quickly found excellent article:
- [Slow in the Application, Fast in SSMS? Understanding Query Plan Mysteries] by Erland Sommarskog.
If you work with SQL Server, I highly recommend reading it.
Here’s the short version.
SQL Server’s query optimizer tries to choose an efficient execution plan for a query. The plan depends on many factors, including the query itself, available indexes, statistics, parameter values, and compilation context.
The optimizer does a remarkable job, but it’s not perfect. Sometimes it chooses a plan that’s far from ideal for the values encountered during a particular execution.
One possible explanation is parameter sniffing. When SQL Server compiles a parameterized query or stored procedure, it can use the parameter values available at compilation time to estimate the number of rows that will be processed. The resulting plan may work well for those values and perform terribly for others.
How do you fix it? That’s the tricky part.
You need to compare good and bad execution plans and understand why the optimizer chose each one. Only then can you decide whether the problem is related to parameter sniffing, indexing, statistics, or something else.
The SQL Server Central article includes a useful script for retrieving cached execution plans.
Comparing Cached Execution Plans
As you can see, the first query has four cached plans. Plans 1 and 3 look particularly bad, judging by their logical reads and execution times. Plans 2 and 4 look much healthier.
This was consistent with my parameter-sniffing hypothesis, although multiple plans alone don’t prove that parameter sniffing is the cause. Different plans can exist for several reasons, including different parameter values, session settings, and compilation contexts.
I then compared the bad plans with the good ones.
In both cases, the underlying issue was a missing index. The better plans managed to filter out most of the rows before reaching the joins that had to work without the appropriate index.
Inspecting the Parameters Used at Compilation
You can also inspect the parameter values SQL Server used when compiling a cached plan.
The following query retrieves cached plans and their compiled parameter values for a stored procedure. It also returns the statement text and the SET options associated with each plan.
DECLARE @procname nvarchar(256) = 'SP_name' - Specify the stored procedure name here.
; WITH basedata AS (
SELECT est.dbid,
qs.statement_start_offset/2 AS stmt_start,
qs.statement_end_offset/2 AS stmt_end,
est.encrypted AS isencrypted, est.text AS sqltext,
epa.value AS set_options, qp.query_plan,
charindex('<ParameterList>', qp.query_plan) + len('<ParameterList>')
AS paramstart,
charindex('</ParameterList>', qp.query_plan) AS paramend
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) est
CROSS APPLY sys.dm_exec_text_query_plan(qs.plan_handle,
qs.statement_start_offset,
qs.statement_end_offset) qp
CROSS APPLY sys.dm_exec_plan_attributes(qs.plan_handle) epa
WHERE est.objectid = object_id (@procname)
- AND est.dbid = db_id(@dbname)
AND epa.attribute = 'set_options'
), next_level AS (
SELECT
dbid,
stmt_start, set_options, query_plan,
CASE WHEN isencrypted = 1 THEN ' - ENCRYPTED'
WHEN stmt_start >= 0
THEN substring(sqltext, stmt_start + 1,
CASE stmt_end
WHEN 0 THEN datalength(sqltext)
ELSE stmt_end - stmt_start + 1
END)
END AS Statement,
CASE WHEN paramend > paramstart
THEN CAST (substring(query_plan, paramstart,
paramend - paramstart) AS xml)
END AS params
FROM basedata
)
SELECT
DB_NAME(dbid) AS [DB_Name],
set_options AS [SET], n.stmt_start AS Pos, n.Statement,
CR.c.value('@Column', 'nvarchar(128)') AS Parameter,
CR.c.value('@ParameterCompiledValue', 'nvarchar(128)') AS [Sniffed Value],
CAST (query_plan AS xml) AS [Query plan]
FROM next_level n
CROSS APPLY n.params.nodes('ColumnReference') AS CR(c)
ORDER BY n.set_options, n.stmt_start, Parameter
The result shows the compiled parameter values and the corresponding execution plan.
Click the query plan in the results to open its XML representation. To view it graphically in SQL Server Management Studio, save the XML to a file with the `.sqlplan` extension and open it.
A note about the example: this script reflects the diagnostic approach used at the time. Before publishing or reusing it, test it against your target SQL Server version and check the statement-offset handling, particularly for statements whose end offset is “-1”. Also note that the result depends on the relevant plans still being present in the plan cache.
What Was Actually Wrong
The investigation eventually led me to two stored procedures affected by parameter sniffing, along with several missing indexes that made some queries more expensive than they needed to be.
I addressed the parameter-sniffing issue by adding OPTION (RECOMPILE) to the problematic queries. This is not always the best solution, since SQL Server has to compile the query again instead of reusing a cached execution plan. However, it can be a reasonable trade-off when plan reuse leads to inconsistent performance.
I also added several indexes to reduce the amount of data SQL Server had to read. Index selection is a topic of its own, so I’ll cover the experiments, execution plans, and performance measurements behind those decisions in a separate article on SQL Server index tuning.
The fix was deployed, and the timeout alerts stopped.
At the time, I had been subscribed to the project’s timeout alerts so that I would be notified whenever one occurred. Almost two years later, I received another alert — actually, two of them. Apparently, nobody had removed me from the notification list.
At least I got a reminder that the fix had apparently been doing its job for nearly two years.
Useful Links
- World Time Buddy (https://www.worldtimebuddy.com/)
- Attention events can cause open transactions and blocking in SQL Server (https://web.archive.org/web/20151004172257/http:/blogs.msdn.com/b/pamitt/archive/2010/11/07/attention-events-causing-open-transaction-and-blocking.aspx)
- Finding Queries the Application Cancelled With Attention Events (https://blog.sqlauthority.com/2020/07/14/finding-queries-the-application-cancelled-with-attention-events/)
- Slow in the Application, Fast in SSMS? Understanding Query Plan Mysteries (https://www.sommarskog.se/query-plan-mysteries.html)
- The Elephant and the Mouse, or, Parameter Sniffing in SQL Server (https://www.brentozar.com/archive/2013/06/the-elephant-and-the-mouse-or-parameter-sniffing-in-sql-server/)
