There are so many ways to look inside SQL Server. New extended events and dynamic management views are introduced every version. But if you want to collect something that’s unavailable, with a little bit of creativity, you can create your own tools.
Inspired by Richie Rump’s latest project, I’m going to describe a tool I wrote and the process I took to get there.
The Problem To Tackle
I had a deadlock graph I wanted to tackle, but I was having trouble reproducing it. I needed to know more about the queries involved. But the query plans were no longer in cache. So here’s the problem
Can I collect the execution plans that were used for the queries involved in a deadlock graph?
I want to use that information to reproduce – and ultimately fix – the deadlock.
The Right Tool For the Job
If you don’t have enough data to get to the root cause of an issue, put something in place for next time.
Can I Use Out-Of-The-Box Extended Events?
I’m getting used to extended events and so my first thought was “Is there a query plan field I can collect with the deadlock extended event? There is not. Which isn’t too surprising. Deadlock detection is independent of any single query.
So How Do I Get To The Execution Plans?
So when I look at a deadlock graph, I can see there are sql_handles. Given that, I can grab the plan_handle and then the query plan from the cache, but I’m going to need to collect it automatically at the time the deadlock is generated. So I’m going to need
- XML shredding skills
- Ability to navigate DMVs to get at the cached query plans
- A way to programatically respond to deadlock graph events (like an XE handler or a trigger)
Responding Automatically to Extended Events
This is when I turned to #sqlhelp. And sure enough, six minutes later, Dave Mason helped me out:
@MJSwart I am really hoping someone answers "yes". Somewhat related…I've used event notifications to fill this need.#sqlhelp
— Dave Mason (@BeginTry) September 21, 2016
I had never heard of Event Notifications, so after some googling, I discovered two things. The first thing is that I can only use Event Notifications with DDL or SQLTrace events rather than the larger set of extended events. Luckily deadlock graphs are available in both. The second thing is that Event Notifications aren’t quite notifications the way alerts are. They’re a way to push event info into a Service Broker queue. If I want automatic actions taken on Service Broker messages, I have to define and configure an activation procedure to process each message. In pictures, here’s my plan so far:
Will It Work?
I think so, I’ve had a lot of success creating my own tools in the past such as
- What statements are responsible for the most transaction log?
- Who’s the lead blocker in a set of blocked process reports?
Also, looking at the different pieces, they’re probably robust enough to do what I need them to do. One surprise involved security concerns for activated procedures that need to access system views
The Deadlock Logging Script
Here’s the tool!
Create the Database
USE master; IF (DB_ID('DeadlockLogging') IS NOT NULL) BEGIN ALTER DATABASE DeadlockLogging SET SINGLE_USER WITH ROLLBACK IMMEDIATE; DROP DATABASE DeadlockLogging; END CREATE DATABASE DeadlockLogging WITH TRUSTWORTHY ON; GO |
Create the Service Broker Objects
I’ve never used Service Broker before, so a lot of this comes from examples found in Books Online.
use DeadlockLogging; CREATE QUEUE dbo.LogDeadlocksQueue; CREATE SERVICE LogDeadlocksService ON QUEUE dbo.LogDeadlocksQueue ([http://schemas.microsoft.com/SQL/Notifications/PostEventNotification]); CREATE ROUTE LogDeadlocksRoute WITH SERVICE_NAME = 'LogDeadlocksService', ADDRESS = 'LOCAL'; -- add server level notification IF EXISTS (SELECT * FROM sys.server_event_notifications WHERE [name] = 'LogDeadlocks') DROP EVENT NOTIFICATION LogDeadlocks ON SERVER; DECLARE @SQL NVARCHAR(MAX); SELECT @SQL = N' CREATE EVENT NOTIFICATION LogDeadlocks ON SERVER FOR deadlock_graph -- name of SQLTrace event type TO SERVICE ''LogDeadlocksService'', ''' + CAST(service_broker_guid as nvarchar(max))+ ''';' FROM sys.databases WHERE [name] = DB_NAME(); EXEC sp_executesql @SQL; GO |
The dynamic SQL is used to fetch the database guid of the newly created database.
a Place to Store Deadlocks
-- Create a place to store the deadlock graphs along with query plan information CREATE SEQUENCE dbo.DeadlockIdentity START WITH 1; CREATE TABLE dbo.ExtendedDeadlocks ( DeadlockId bigint not null, DeadlockTime datetime not null, SqlHandle varbinary(64), StatementStart int, [Statement] nvarchar(max) null, Deadlock XML not null, FirstQueryPlan XML ); CREATE CLUSTERED INDEX IX_ExtendedDeadlocks ON dbo.ExtendedDeadlocks(DeadlockTime, DeadlockId); GO |
The Procedure That Processes Queue Messages
CREATE PROCEDURE dbo.ProcessDeadlockMessage AS DECLARE @RecvMsg NVARCHAR(MAX); DECLARE @RecvMsgTime DATETIME; SET XACT_ABORT ON; BEGIN TRANSACTION; WAITFOR ( RECEIVE TOP(1) @RecvMsgTime = message_enqueue_time, @RecvMsg = message_body FROM dbo.LogDeadlocksQueue ), TIMEOUT 5000; IF (@@ROWCOUNT = 0) BEGIN ROLLBACK TRANSACTION; RETURN; END DECLARE @DeadlockId BIGINT = NEXT VALUE FOR dbo.DeadlockIdentity; DECLARE @RecsvMsgXML XML = CAST(@RecvMsg AS XML); DECLARE @DeadlockGraph XML = @RecsvMsgXML.query('/EVENT_INSTANCE/TextData/deadlock-list/deadlock'); WITH DistinctSqlHandles AS ( SELECT DISTINCT node.value('@sqlhandle', 'varchar(max)') as SqlHandle FROM @RecsvMsgXML.nodes('//frame') AS frames(node) ) INSERT ExtendedDeadlocks (DeadlockId, DeadlockTime, SqlHandle, StatementStart, [Statement], Deadlock, FirstQueryPlan) SELECT @DeadlockId, @RecvMsgTime, qs.sql_handle, qs.statement_start_offset, [statement], @DeadlockGraph, qp.query_plan FROM DistinctSqlHandles s LEFT JOIN sys.dm_exec_query_stats qs on qs.sql_handle = CONVERT(VARBINARY(64), SqlHandle, 1) OUTER APPLY sys.dm_exec_query_plan(qs.plan_handle) qp OUTER APPLY sys.dm_exec_sql_text (CONVERT(VARBINARY(64), SqlHandle, 1)) st OUTER APPLY ( SELECT SUBSTRING(st.[text],(qs.statement_start_offset + 2) / 2, (CASE WHEN qs.statement_end_offset = -1 THEN LEN(CONVERT(NVARCHAR(MAX), st.text)) * 2 ELSE qs.statement_end_offset + 2 END - qs.statement_start_offset) / 2)) as sqlStatement([statement]); -- clean up old deadlocks DECLARE @limit BIGINT SELECT DISTINCT TOP (500) @limit = DeadlockId FROM ExtendedDeadlocks ORDER BY DeadlockId DESC; DELETE ExtendedDeadlocks WHERE DeadlockId < @limit; COMMIT GO |
Activating the Procedure
ALTER QUEUE dbo.LogDeadlocksQueue WITH ACTIVATION ( STATUS = ON, PROCEDURE_NAME = dbo.ProcessDeadlockMessage, MAX_QUEUE_READERS = 1, EXECUTE AS SELF ); GO |
Clean Up
And when you’re all done, this code will clean up this whole experiment.
use master; if (db_id('DeadlockLogging') is not null) begin alter database DeadlockLogging set single_user with rollback immediate drop database DeadlockLogging end if exists (select * from sys.server_event_notifications where name = 'DeadlockLogging') DROP EVENT NOTIFICATION LogDeadlocks ON SERVER; |
Hi Michael,
great work. Seems to be somewhat related to the work of Michael Bourgon in his Overlord monitoring project (http://thebakingdba.blogspot.de/2015/06/presenting-overlord-my-24-hours-of-pass.html).
Perhaps you two could put it together into one solution?
Cheers
Martin
Comment by Martin Guth — September 26, 2016 @ 3:49 am
[…] Michael J. Swart comes up with a system to collect execution plans at the time of a deadlock and log…: […]
Pingback by Automating Deadlock Execution Plan Collection – Curated SQL — September 26, 2016 @ 8:00 am
Hi Martin,
The value I was hoping to give in this post was a description of the method I used when an off-the-shelf solution is not readily available for monitoring.
A lot of the code I use is taken from books online. But anyone may make use of this code in any way they see fit.
Comment by Michael J. Swart — September 26, 2016 @ 9:04 am
Michael, did this work? My concern is if the query plan information would still there by the time the event gets processed through Service Broker.
Comment by C Gray — September 26, 2016 @ 10:55 am
Hi C Gray,
Yes, this did work. In my case, the deadlocks are infrequent enough that any deadlocks that are generated go through the queue and are processed in a matter of a few seconds. The one thing I was counting on is that the query plan does get cached (in other words, no WITH RECOMPILE hints were used) and that it didn’t fall out of cache quickly.
My previous attempt at collecting deadlocks https://michaeljswart.com/go/deadlocks, suffered from the fact that it sometimes took hours or days for me to decide to inspect deadlock graphs. In that case, the cached plans were definitely long gone.
So this solution does work very nicely in practice.
Now if cached query plans did get evicted too quickly, then (1) I would have wondered why query plans were getting evicted from cache so rapidly? or (2) I might have considered using query store (which requires 2016).
Comment by Michael J. Swart — September 26, 2016 @ 11:05 am
[…] about using Event Notifications to collect execution plans related to deadlocks in his post, “Build Your Own Tools“. Just don’t try to run before you walk: this is pretty advanced stuff and you need to […]
Pingback by Free Blocking and Deadlock Monitoring for SQL Server - by Kendra Little — September 29, 2016 @ 11:17 am