I'm seeing the following in my logs: Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding. This happens intermittently on a server that is currently not utilized at all. How can it be timing out if hardly any usage is occurring? How can I track this down? Thank you for any assistance you can provide.

By default, most client APIs wait for 30 seconds and if SQL Server has not completed within that time frame they will send an signal to SQL Server to stop executing the batch return the error "timeout expired" to SQL Server. The most common reason why this is happen is that the query is slow and would need more time to execute. The next most common reason is blocking. I don't know if in the context of Azure SQL Database it could be a matter or network issues. That is, the response from SQL Server gets lost somewhere. But I would expect that to manifest in a different way. I would recommend that you enhance your logging to see which statements that gets blocked, so that you can find the pattern.

Connection termination errors may occur because the database or elastic pool is temporarily unavailable. They may also occur because of various problems in the network infrastructure between the database server and the client application, including firewalls, network appliances, etc. These problems may be transient or permanent. As a general guidance, applications should use a fixed number of retry attempts for these errors before considering them permanent failures. See this link to diagnose this error: https://learn.microsoft.com/en-us/azure/azure-sql/database/troubleshoot-common-errors-issues?view=azuresql

Azure Sql Server Intermittent Timeouts

Accepted answer

Erland Sommarskog 110.2K Reputation points

2024-03-03T12:14:28.8+00:00

By default, most client APIs wait for 30 seconds and if SQL Server has not completed within that time frame they will send an signal to SQL Server to stop executing the batch return the error "timeout expired" to SQL Server.

The most common reason why this is happen is that the query is slow and would need more time to execute. The next most common reason is blocking. I don't know if in the context of Azure SQL Database it could be a matter or network issues. That is, the response from SQL Server gets lost somewhere. But I would expect that to manifest in a different way.

I would recommend that you enhance your logging to see which statements that gets blocked, so that you can find the pattern.
Please sign in to rate this answer.
Mike-E-angelo 496 Reputation points

2024-03-03T12:57:16.3433333+00:00

Thank you for your reply. As mentioned this is intermittent, so I do not think the query is slow. What I am looking for is a way to see what happened on Sql Server. It seems like this information would be readily available and I should not have to modify anything about my application. Thank you for your continued assistance.

Erland Sommarskog 110.2K Reputation points

2024-03-03T13:48:07.3733333+00:00

Keep in mind that I don't know anything about your application. For all I care you could be submitting all sorts of queries, of which some prove to be slow. And for that matter, even if is the same query, you may be calling it with different parameters. It's quite a different between asking for orders only submitted today, or for all orders since 1990.

But as I mentioned, the reason can also be blocking, and blocking can be intermittent as it depends on what other processes are doing.

In SQL Server there is a not a whole lot of information about this. Keep in mind that it is the client that grows tired of waiting. SQL Server itself don't mind running a query for hours.

What SQL Server notices is that the client sends an attention signal, and on that signal SQL Server stops executing the current batch.

There are three ways SQL Server can register this event:

Extended events.

Trace.

Query Store.

For the first two, you need to actually set up X-event/Trace sessions to capture the event. For Query Store, you need to do is to enable Query Store, but since you are on Azure SQL Database, Query Store is enabled by default.

To find aborted executions, you can run

SELECT * FROM sys.query_store_runtime_stats WHERE execution_type = 3

The column runtime_stats_interval_id maps to sys.query_store_runtime_stats_interval that gives you time period for the interval. By default, run-time statistics are stored by the hour.

There is also a plan_id which joins to sys.query_store_plan, and query you have a query_id which joins to sys.query_store_query, and here finally you have a query_text_id that takes you to sys.query_store_query_text where you can find the actual query text.

Finally, there is also sys.query_store_wait_stats, which you could use to determine whether the execution might have been related to blocking. Again, you can filter here for execution_type = 3 to only get executions aborted by attention signals. This view also has a runtime_stats_interval_id and a plan_id.

But in the end, it is better to put the diagnostics in the client, I think, as the client has more context of what it wanted to do.

Mike-E-angelo 496 Reputation points

2024-03-03T15:58:29.76+00:00

Thank you @Erland Sommarskog that was more along the lines of what I was looking for. I ran that query but the only thing I see is from 2/18, last month:

For more context on my side. I have had my server very busy (relatively) with many purchases without any timeouts. Now I am going through a bit of a quiet time and suddenly I get an error when a user makes a purchase and a timeout occurs.

I did look into sys.query_store_wait_stats and it does have some entries but it does not appear to contain a datetime column. How do I correlate this? Thank you for any further guidance you can provide.

Erland Sommarskog 110.2K Reputation points

2024-03-03T18:07:16.4566667+00:00

Note that you had in total five attention signals within a minute for two different query plans. You can look at the cpu time columns to get an idea whether it was slow execution or blocking. If CPU time is very low, it is likely to be blocking. The times you see are in microseconds.

It is worth pointing out that the main purpose of Query Store is to be a tuning aid. That is, this where you go to find your slow queries to tune them. Query Store is also designed to produce minimal overhead. You can set Query Store to capture exactly all queries, but the default capture mode is AUTO, which means that infrequently executed queries may be ignored. Therefore, not all attention signals may be registered in Query Store.

I did look into sys.query_store_wait_stats and it does have some entries but it does not appear to contain a datetime column. How do I correlate this?

The start and end for the intervals are in sys.query_store_runtime_intervals and runtime_stats_interval is the column to join over.

Mike-E-angelo 496 Reputation points

2024-03-03T18:15:04.4933333+00:00

Thank you for the continued guidance, Erland. I hear you about Query Store being a tuning aid, but unfortunately, it also appears to be the only viable place to get any sort of idea of what is happening to my Azure Sql Server instance. I have been poking and prodding through this offering for over two years now and feel about as helpless about what is actually occurring on my instance now as I did when I started. The Azure Portal is pretty useless, using both the Query Performance Index and Performance blades seem to be missing many many pieces of critical information. It is most impossible to know and understand what is happening with this product, especially for those who are newer on the Azure adoption scale.

Ranting aside, I am getting the following:

Erland Sommarskog 110.2K Reputation points

2024-03-03T18:20:27.8033333+00:00

Sorry, the name is sys.query_store_runtime_stats_interval. (It was also in my previous post.)

Mike-E-angelo 496 Reputation points

2024-03-03T18:26:07.2566667+00:00

Thank you, I was able to get the join but everything I am seeing is from 2/18:

Erland Sommarskog 110.2K Reputation points

2024-03-03T19:13:06.56+00:00

Yes, we new already knew this from the output from sys.query_stats_runtime_stats that the only attention signals registered in Query Store are in this hour. But at least it is a start to get a hint of what is going on. But you need to look at what are in those waits to the right in the result set.

As for why not more queries are registered, you should know that in this context

SELECT ... FROM Orders WHERE OrderID = 11000 SELECT ... FROM Orders WHERE OrderID = 11001

are two different queries. This happens if you are building queries this way:

cmd.CommandText = "SELECT ... FROM Orders WHERE OrderID = " + OrderID.ToString();

And since each query may only be executed occasionally, they are not very likely to be registered in Query Store.

If you instead use parameterised statements:

cmd.CommandText = "SELECT ... FROM Orderds WHERE OrderID = @OrderID"; cmd.Paramaters.Add("@OrderID", SqlDBTypes.Int).Value = OrderID;

All is the same query when it comes to Query Store and the SQL Server plan cache. The latter is very much best practice for a number of reasons.

Finally, I should add that SQL Server does not know why the attention signal was produced. It can be produced in more than one way. For instance, that red button in SSMS also sends an attention signal.

Mike-E-angelo 496 Reputation points

2024-03-03T19:18:42.2+00:00

Thank you for the further suggestions. Be aware that I am using Entity Framework which automatically parameterizes all queries.

Deleted

This comment has been deleted due to a violation of our Code of Conduct. The comment was manually reported or identified through automated detection before action was taken. Please refer to our Code of Conduct for more information.

Mike-E-angelo 496 Reputation points

2024-03-04T10:15:17.4633333+00:00

Hi @Erland Sommarskog after poking around I believe I found what is causing the issue. My guess is that the SQL server's cache plan expired after little use and it has to recompile a query. Could this be possible? How long does a plan last in memory (and is there a way to increase this so it's forever :))?

Anyways, the mystery continues here. This is a very simple query between two tables with only thousands of rows in each table but it seems a good majority of time is spent in a clustered key lookup.

SELECT CASE WHEN EXISTS ( SELECT 1 FROM [ExternalProcess] AS [e] WHERE [e].[Discriminator] = N'IssuanceProcess' AND ( SELECT TOP(1) [p].[Status] FROM [ProcessUpdate] AS [p] WHERE [e].[Id] = [p].[ExternalProcessId] ORDER BY [p].[Id] DESC) = 4) THEN CAST(1 AS bit) ELSE CAST(0 AS bit) END

This takes nearly 90 seconds to compile. Note that the above is EFCore's query based on how I have wrote the query in C#. If I do a straight join, it still takes about 32 seconds, which still seems like quite a lot of time.

Erland Sommarskog 110.2K Reputation points

2024-03-04T22:25:43.9466667+00:00

A plan can fall out of the cache if there is memory pressure. What also can happen is that something can trigger a recompile, for instance autostats. (Which occurs if there have a certain amount of updates to the table.) Finally, we should not forget that there can be failovers in Azure. Your database has three replicas, and which is the primary may change. In case of a failover, the cache is lost entirely.

Are you saying that the query above takes 90 seconds to compile? That is, if you re-execute it, you get a response a lot faster? That's a fairly simple query, which I would expect to compile in 100 ms or so. Or do you mean that it takes 90 seconds to execute? For some thousands of rows in each table that extremely excessive.

Which Pricing Tier is your database in?

Mike-E-angelo 496 Reputation points

2024-03-05T07:58:37.2566667+00:00

That's all very good information @Erland Sommarskog thank you for providing valuable replies for me here. It is appreciated. The server has very little traffic right now, so memory pressure does not seem like a candidate. Maybe autostats might be a candidate as this table was getting updates (but very few relatively).

Along those lines, I basically spent the morning yesterday diving into this issue. To start, I was wrong about ProcessUpdate, to my surprise it has over half a million rows at 571K, and ExternalProcess has approximately 90K. Still, it's not millions and it would seem that this would be an easy plan to compile.

The other issue is that I have been trying to get by with an S1 for as long as possible, attempting to cut costs. So that has a big impact with performance. I did try upgrading to the serverless General Purpose and that seems much faster (but not sure how that will impact cost yet). It takes ~16 seconds to compile that query plan now down from the 90 seconds (or more -- sometimes up to 2.5 minutes) with the S1.

Finally, yes, when I say 90 seconds I mean compile times. That is a blocking event, correct? (Subsequent times are lightning fast of course.) If for some reason the plan is evicted and the server has to recompile it, it blocks it and another process looking to use that table will essentially hang until it has been compiled. In the case of an application/client thread as in the one I originally reported in this issue, it will fail with a timeout issue. That is my understanding of this scenario at the moment.

Erland Sommarskog 110.2K Reputation points

2024-03-05T20:25:16.34+00:00

S1 - yes, that is not very powerful. Furthermore, on an S1, I believe you can be a victim to "noisy neighbours". That is, other databases on the same physical machine may add load that affects your database.

I have an S1 database myself (for test purposes only), and I've noticed that a test case I have for a certain SQL feature runs for several minutes on the S1, while it completes in maybe 30 seconds on my desktop.

I have two serverless General Purpose, and they certainly perform better. Except when they start up of course. But if you are running some sort of web commerce, you probably don't want serverless. Serverless is great for test/dev that you only use occasionally, but for something that is on all the time, a provisioned instance is better.

And, yes, the price tag will be stiffer. I only have a credit that comes with my VS subscription, and if I leave the serverless databases on, I outrun the credit before the month is over.

Finally, yes, when I say 90 seconds I mean compile times. That is a blocking event, correct?

Normally, "blocking" refers to when you cannot access a row, because is blocked by another process. In Azure SQL Database, the default setting is READ_COMMITTED_SNAPSHOT, which means that readers and writers cannot block each other. But a writer can be blocked by another writer.

16 seconds in compile time for that relatively simple query is still quite excessive. Unless these ProcessUpdate and ExternalProcess are view of big complexity.

Mike-E-angelo 496 Reputation points

2024-03-06T07:38:46.0766667+00:00

Thank you for your continued insight, Erland. 🙏

And, yes, the price tag will be stiffer

This is ironic because it says it's the most budget friendly, which is why I am trying it out:

Normally, "blocking" refers to when you cannot access a row

This could also occur if a process is looking up all keys in a table, correct?

16 seconds in compile time for that relatively simple query is still quite excessive

I agree. To be sure, it's not compiling (I do not think?) but spending its time looking up all keys in a table. Or maybe that's considering compiling (the plan). Either way it's an incredible amount of time up front the first time and lightning fast thereafter. If you have any suggestions on how to investigate and improve this I would greatly appreciate it.

Erland Sommarskog 110.2K Reputation points

2024-03-06T20:20:23.13+00:00

Well compared to Hyperscale and Business Critical, General Purpose is budget friendly. What I don't know of the top of my head is whether General Purpose or Premium is a better deal. But the DTU-based models are an older line, and the whole DTU concept is somewhat opaque.

"Compiling" refers to the time it takes to build the plan. Even if there is a compiled plan, the first execution can take longer time than subsequent executions, since data may to be read from disk the first time, whereas it is in cache the next time. I would guess that these are the 16/90 seconds you are seeing.

To see the compilation time for a query, run with Actual Execution Plan enabled, then click the left-most operator and select Properties. You see the CompileTime to the right (together which a bunch of other information). The time is in milliseconds, I believe.

Mike-E-angelo 496 Reputation points

2024-03-08T09:27:26.33+00:00

Thank you very much for your valuable assistance, Erland! You have been very helpful. After some time yesterday I was able to have some success by using a view:

CREATE VIEW View_ExternalProcess_Status AS SELECT [e].Id, [e].Discriminator, p.[Status] FROM [ExternalProcess] AS [e] JOIN [ProcessUpdate] AS [p] ON [e].[Id] = [p].[ExternalProcessId] AND p.Id = (SELECT TOP(1) Id FROM ProcessUpdate p2 WHERE p2.ExternalProcessId = e.Id ORDER BY Id DESC)

This query now takes only four seconds to compile on an S1:

CHECKPOINT; GO DBCC DROPCLEANBUFFERS; GO DBCC FREEPROCCACHE; SELECT CASE WHEN EXISTS ( SELECT 1 FROM View_ExternalProcess_Status e WHERE [e].[Discriminator] = N'IssuanceProcess' AND [Status] = 4) THEN CAST(1 AS bit) ELSE CAST(0 AS bit) END

From now on I will be more aware of stalls/waits such as what I have experienced here and see if I can resolve it with a Sql View. 👍

Mike-E-angelo 496 Reputation points

2024-03-08T09:31:17.5266667+00:00

Wow, I just spent 10 minutes typing a reply and it was deleted for Code of Conduct violation? Weak. It would be great to get that comment undelete because it shows how I solved this problem. Are you able to find someone to do this @Erland Sommarskog ? Thank you for your assistance all around.

Mike-E-angelo 496 Reputation points

2024-03-08T09:31:58.75+00:00

I cannot seem to post comments anymore.

Mike-E-angelo 496 Reputation points

2024-03-08T09:32:33.9033333+00:00

OK nevermind this system is pretty terrible. It takes a minute or so for comments to display. Horray "cloud technology." :P

Erland Sommarskog 110.2K Reputation points

2024-03-08T22:03:59.27+00:00

Thank you very much for your valuable assistance, Erland! You have been very helpful. After some time yesterday I was able to have some success by using a view:

Apparently, that simplification of the query did wonders. Good work!

Wow, I just spent 10 minutes typing a reply and it was deleted for Code of Conduct violation

Yeah, the automatic spam detection here can overly aggressive sometimes. Since I am a moderator, I had the powers to resurrect the post.

OK nevermind this system is pretty terrible. It takes a minute or so for comments to display.

Yeah, they could a better work there.
Sign in to comment

Use comments to ask for clarification, additional information, or improvements to the question.

Share via

Azure Sql Server Intermittent Timeouts

1 additional answer

Your answer