Query timeouts when duration is under a second

Question

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:

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 timeouts 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.)

I thought it might be blocking, so I setup a Blocked Process Report extended event to see (following this guide). While there are blocks happening on the server, they are not on the databases that my query is running against.

The application is using a API called Dapper (a fairly popular Micro ORM that I hear is used to run Stack Exchange). 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.

The timeout of the query in the application is set to 120 seconds. That should be plenty of time to get most of the queries that I am seeing reported as timeouts.

Answer 1

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.