Monitoring for Timeouts

The question came up at SQL Rally, “Can you use Extended Events to monitor for query timeouts?”

My immediate response was yes… and then I stood there trying to think of exactly how I’d do it. Nothing came quickly to mind. So, I promised to track down the answer and post it to the blog.

My first thought is to use the Causality Tracking feature to find all the places where you have a sql_batch_starting without a sql_batch_completed (or the same thing with rpc calls). And you know what, that would work. But, before I got too deep in trying to write the query that would find all the mismatched attach_activity_id values that have a sequence of 1, but not one of 2, I did some additional reading. Seems there’s another little trick that works even better (sort of). It’s to set up an Event Pairing Target.

This is pretty slick. Here’s the code I used to set up for “timeouts” in SQL Server Management Studio:

CREATE EVENT SESSION [Timeouts] ON SERVER
ADD EVENT sqlserver.sql_batch_completed (
    ACTION (sqlserver.session_id)
    WHERE ([result] <> (2))),
ADD EVENT sqlserver.sql_batch_starting (
    ACTION (sqlserver.session_id))
ADD TARGET package0.pair_matching (SET begin_event = N'sqlserver.sql_batch_starting',
                                   begin_matching_actions = N'sqlserver.session_id',
                                   begin_matching_columns = N'batch_text',
                                   end_event = N'sqlserver.sql_batch_completed',
                                   end_matching_actions = N'sqlserver.session_id',
                                   end_matching_columns = N'batch_text')
WITH (MAX_MEMORY = 4096 KB,
      EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
      MAX_DISPATCH_LATENCY = 30 SECONDS,
      MAX_EVENT_SIZE = 0 KB,
      MEMORY_PARTITION_MODE = NONE,
      TRACK_CAUSALITY = ON,
      STARTUP_STATE = OFF)
GO

A couple of notes. You see the “timeout” in quotes above. That’s because I wasn’t getting a timeout in SSMS, despite setting one. Rather than muck around (I’ll figure that out later), I just set a long running query and then stopped it, but, I put a filter in place to not capture batches that terminated from an Abort command, [result] <> 2. But that did it. As soon as I aborted, I could use the query supplied at the link for Event Pairing Target to immediately see my unmatched pair. That’s quick and easy timeout monitoring using extended events. Output here:

<event name="sql_batch_starting" package="sqlserver" timestamp="2015-03-10T17:25:14.089Z">
    <data name="batch_text">
      <type name="unicode_string" package="package0" />
      <value>SELECT  *
FROM    Production.ProductCostHistory AS pch,
        Production.BillOfMaterials AS bom,
        Person.ContactType AS ct;</value>
    </data>
    <action name="session_id" package="sqlserver">
      <type name="uint16" package="package0" />
      <value>63</value>
    </action>
    <action name="attach_activity_id_xfer" package="package0">
      <type name="activity_id_xfer" package="package0" />
      <value>1BF4899F-4B74-434B-9CDE-2B646A560FB1-0</value>
    </action>
    <action name="attach_activity_id" package="package0">
      <type name="activity_id" package="package0" />
      <value>4B92C757-F780-4D8C-B1DA-F95C206A32EE-1</value>
    </action>
  </event>

So, here’s the biggest question, would I actually use this in production?

I’m a little nervous about using the batch_text as a matching point. With rpc_completed you could just use session_id and object_name or object_id. That’d be great. So, if I were going to use this in production, I’d probably only monitor for certain databases, putting tighter filtering in place for batch commands. But, other than that, I can query the target and pull out any timeout objects, so this is actually pretty slick and works well.

The only shortcoming I see is that you can’t add two pair matching targets in a session, so you would need one session for batch timeouts and another for rpc timeouts. Not the end of the world, but worth noting.