1

We are getting the following exception in an application:

Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.

So, I looked at the query and sure enough it was taking a really long time. So I tuned it up to take less than a second.

But I am still getting timeouts.

So I set up a Extended Events session for the Attention event to catch the timeouts and see what what going on (using this page as a guide).

The results were confusing. I see my queries in the list, but the duration logged in the trace is under a second!

Here are some example values I am getting in duration column for the timeout:
539
539
474
423
505
904

I am confused. Why am I getting an SQL Server timeout error, when the duration shows an average of a half a second?

NOTE: The output from the extended event shows some rows that are 30+ seconds. These are legit timouts to my view and I am working on those. (I just point this out to show that the Attention extended event seems to be working for those queries.)

bumped to the homepage by Community 22 hours ago

This question has answers that may be good or bad; the system has marked it active so that they can be reviewed.

  • 2
    Maybe they are being blocked for more than 30 seconds. – Aaron Bertrand Jan 3 '18 at 23:47
  • Is the connection not closing? – indiri Jan 4 '18 at 0:36
  • The application may have an arbitrary timeout. We are dealing with one now where the vendor has a hard-coded timeout of 5 seconds. They forgot to test that part with a lot of data in the database, so even though the query isn't really timing out, the application is only giving it 5 seconds before it considers it to be timed out. – Tony Hinkle Jan 4 '18 at 2:00
  • @AaronBertrand - I thought the same thing yesterday. So I setup a Blocked Process Report extended event to see (Following this guide: brentozar.com/archive/2014/03/extended-events-doesnt-hard). While there are blocks happening on the server, they are not on the databases that my query is running against.... – Vaccano Jan 5 '18 at 0:00
  • @indiri - The application is using a API called Dapper (a fairly popular Micro ORM that I hear is used to run StackExchange). I imagine it has decent connection management in it. But even if they misused its connections, as I understand it, that leads to resource leaks, not SQL Timeouts... – Vaccano Jan 5 '18 at 0:11
0

I have realized that what ever duration is, it is not the time that the timedout query ran for. I ran waitfor delay '00:00:30' in a query window set to timeout in 10 seconds. The results should have been 10 seconds for all of the time outs. But I got these values for my 6 tests: 70707, 311, 269, 264, 3442, 272. My guess is that duration is the amount if time it took to handle the Attention event (i.e. Stop the query).

Just to be sure that the duration wouldn't work correctly with an actual running query, I ran a long running one, again set to timeout in 10 seconds. The durations where: 64246, 58002, 52828, 68061, 48153, 49084. They took longer, but none of those times is close to 10 seconds. Again, confirms that duration is not what it seems to be.

The documentation says duration is in Microseconds (not milliseconds). That also could work if it is the time to handle the Attention event, but it would never match up to the time it took for the timed out query to run.

I ran the long running query without a time out and had to stop it after 120 seconds. It took a lot longer to stop, and the duration for the Attention event was 6400055. 6.4 seconds is about how long it took to stop. Again confirming that duration is the amount of time it takes to handle the "Attention" event.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.