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:
— 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 dynanmic 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
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;