One DBA's Ongoing Search for Clarity in the Middle of Nowhere


*or*

Yet Another Andy Writing About SQL Server

Wednesday, October 18, 2017

And YOU Get a Deadlock and YOU Get a Deadlock and EVERYBODY GETS A DEADLOCK!

https://memegenerator.net/img/instances/400x/59507872/you-get-a-deadlock-everybody-gets-a-deadlock.jpg
We all get them at one point or another - deadlocks.

I have Object 1 and need Object 2, you have Object 2 and need Object 1:

https://i-technet.sec.s-msft.com/dynimg/IC4289.gif
This isn't the same as simple blocking, where I have Object 1 and you want it (but you can't have it because it's MINE!)  In that case you just need to wait your turn, and eventually you will get sick of waiting and walk away (timeout) or I will get done with it and surrender it to you.

In the deadlock case, there truly is no way out other than terminating one of the two requests - in the example above transaction 1 needs access to the Part table to proceed with its work on the Supplier table, and transaction 2 needs access to the Supplier table to work with the Part table.  This means everyone is stuck.

A great (yet sad) non-techie way of describing a deadlock is this:

https://cdn.meme.am/instances/27106434/no-job-because-no-experience-no-experience-because-no-job.jpg
--

SQL Server has a process called the Deadlock Monitor that periodically watches for deadlock situations and handles them by terminating one or more processes to clear the logjam.  As described in Technet:
By default, the Database Engine chooses as the deadlock victim the session running the transaction that is least expensive to roll back. Alternatively, a user can specify the priority of sessions in a deadlock situation using the SET DEADLOCK_PRIORITY statement. DEADLOCK_PRIORITY can be set to LOW, NORMAL, or HIGH, or alternatively can be set to any integer value in the range (-10 to 10). The deadlock priority defaults to NORMAL. If two sessions have different deadlock priorities, the session with the lower priority is chosen as the deadlock victim. If both sessions have the same deadlock priority, the session with the transaction that is least expensive to roll back is chosen. If sessions involved in the deadlock cycle have the same deadlock priority and the same cost, a victim is chosen randomly.
"Least Expensive to Roll Back" can sometimes be difficult to determine although a general guideline is that SELECT statements are the least expensive (with no LOG to roll back) and are frequent deadlock victims.

--

With all of that in hand, how do you gather information about deadlocks?  Classical deadlock troubleshooting relies on trace flags 1204 and 1222 or a SQL Server trace on the Deadlock Chain and Deadlock Graph events (as described in this MSSQLTip).
https://www.toonpool.com/user/589/files/living_in_the_past_333905.jpg

We all know at this point (whether some people want to admit it or not) that Extended Events are the tool of the future for this kind of work.  They are more lightweight than SQL Server Trace and are continuing to be improved (unlike Trace, which has been stagnant since SQL Server 2005!)  Any time you find yourself using Trace or Profiler you should pause and reflect on how to accomplish the same task with XEvents.

In this case, there is deadlock information in the System_Health Session, the basic session deployed by default on all SQL Server instances since SQL Server 2008.  (Think the better, stronger, faster version of the Default Trace.)  Patrick Keisler (blog/@PatrickKeisler) has a great write-up about the System_Health session on his blog here.

By default deadlock information is one giant character field that is formatted for XML.  The XML is readable (sort of) if that's your thing:

--
<deadlock>

  <victim-list>
    <victimProcess id="process5776a5498" />
  </victim-list>
  <process-list>
    <process id="process5776a5498" taskpriority="0" logused="0" waitresource="KEY: 19:72057594040745984 (9ba325989765)" waittime="4168" ownerId="327954909" transactionname="SELECT" lasttranstarted="2017-10-17T17:21:04.417" XDES="0x50560f9d0" lockMode="S" schedulerid="1" kpid="3756" status="suspended" spid="64" sbid="0" ecid="0" priority="0" trancount="0" lastbatchstarted="2017-10-17T17:21:04.417" lastbatchcompleted="2017-10-17T17:21:03.293" lastattention="1900-01-01T00:00:00.293" hostpid="4012" loginname="Login1" isolationlevel="read committed (2)" xactid="327954909" currentdb="19" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128056">
      <executionStack>
        <frame procname="adhoc" line="1" sqlhandle="0x0200000096663f042d323a9d19c06335abb6318e18e6f8750000000000000000000000000000000000000000">
SELECT dbo.Fred_Table7.ObjectID FROM dbo.Fred_Table7 WHERE (dbo.Fred_Table7.ObjectID not  in (23) AND dbo.Fred_Table7.ObjectID &lt;= 4294966615 AND (dbo.Fred_Table7.LastModifyTime &gt;CAST('2017 10 17 20 08 18 115' AS VARBINARY(32)) OR dbo.Fred_Table7.LastModifyTime =CAST('2017 10 17 20 08 18 115' AS VARBINARY(32)) AND dbo.Fred_Table7.ObjectID &gt; 2404307) AND (dbo.Fred_Table7.SI_INSTANCE_OBJECT = 0 AND dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 0  OR (dbo.Fred_Table7.SI_INSTANCE_OBJECT = 1 OR dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 1)  AND dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 0 AND dbo.Fred_Table7.ScheduleStatus = 1) AND dbo.Fred_Table7.TypeID in (2, 8, 21, 67, 68, 260, 261, 262, 266, 267, 270, 271, 272, 277, 279, 281, 282, 289, 295, 301, 337, 338, 339, 340, 343, 349, 351, 355, 358, 361, 365, 368, 372, 373, 379, 385, 387, 389, 391, 394, 396, 407, 408, 414, 415, 430, 431) AND (SI_PLUGIN_OBJECT = 0) AND dbo.Fred_Table7.SI_HIDDEN_OBJECT = 0) ORDER BY dbo    </frame>
      </executionStack>
      <inputbuf>
SELECT dbo.Fred_Table7.ObjectID FROM dbo.Fred_Table7 WHERE (dbo.Fred_Table7.ObjectID not  in (23) AND dbo.Fred_Table7.ObjectID &lt;= 4294966615 AND (dbo.Fred_Table7.LastModifyTime &gt;CAST('2017 10 17 20 08 18 115' AS VARBINARY(32)) OR dbo.Fred_Table7.LastModifyTime =CAST('2017 10 17 20 08 18 115' AS VARBINARY(32)) AND dbo.Fred_Table7.ObjectID &gt; 2404307) AND (dbo.Fred_Table7.SI_INSTANCE_OBJECT = 0 AND dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 0  OR (dbo.Fred_Table7.SI_INSTANCE_OBJECT = 1 OR dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 1)  AND dbo.Fred_Table7.SI_RUNNABLE_OBJECT = 0 AND dbo.Fred_Table7.ScheduleStatus = 1) AND dbo.Fred_Table7.TypeID in (2, 8, 21, 67, 68, 260, 261, 262, 266, 267, 270, 271, 272, 277, 279, 281, 282, 289, 295, 301, 337, 338, 339, 340, 343, 349, 351, 355, 358, 361, 365, 368, 372, 373, 379, 385, 387, 389, 391, 394, 396, 407, 408, 414, 415, 430, 431) AND (SI_PLUGIN_OBJECT = 0) AND dbo.Fred_Table7.SI_HIDDEN_OBJECT = 0) ORDER BY db   </inputbuf>
    </process>
    <process id="process1b9313868" taskpriority="0" logused="284" waitresource="KEY: 19:72057594041008128 (1679744d2988)" waittime="4168" ownerId="327954910" transactionname="implicit_transaction" lasttranstarted="2017-10-17T17:21:04.417" XDES="0x57788c3a8" lockMode="X" schedulerid="2" kpid="11128" status="suspended" spid="60" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2017-10-17T17:21:04.417" lastbatchcompleted="2017-10-17T17:21:04.417" lastattention="1900-01-01T00:00:00.417" hostpid="4012" loginname="Login1" isolationlevel="read committed (2)" xactid="327954910" currentdb="19" lockTimeout="4294967295" clientoption1="671088672" clientoption2="128058">
      <executionStack>
        <frame procname="adhoc" line="1" stmtstart="86" sqlhandle="0x0200000011d6ca3a9ba3506e8d74888b6554043825c5204e0000000000000000000000000000000000000000">
UPDATE dbo.Fred_Table7 SET Version = @P1, LastModifyTime = @P2 WHERE ObjectID = @P3 AND Version = @P4    </frame>
        <frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
unknown    </frame>
      </executionStack>
      <inputbuf>
(@P1 int,@P2 varbinary(32),@P3 int,@P4 int)UPDATE dbo.Fred_Table7 SET Version = @P1, LastModifyTime = @P2 WHERE ObjectID = @P3 AND Version = @P4   </inputbuf>
    </process>
  </process-list>
  <resource-list>
    <keylock hobtid="72057594040745984" dbid="19" objectname="Database12.dbo.Fred_Table7" indexname="ObjectID_I7" id="lock52e379a80" mode="X" associatedObjectId="72057594040745984">
      <owner-list>
        <owner id="process1b9313868" mode="X" />
      </owner-list>
      <waiter-list>
        <waiter id="process5776a5498" mode="S" requestType="wait" />
      </waiter-list>
    </keylock>
    <keylock hobtid="72057594041008128" dbid="19" objectname="Database12.dbo.Fred_Table7" indexname="LastModifyTime_I7" id="lock35b41fa80" mode="S" associatedObjectId="72057594041008128">
      <owner-list>
        <owner id="process5776a5498" mode="S" />
      </owner-list>
      <waiter-list>
        <waiter id="process1b9313868" mode="X" requestType="wait" />
      </waiter-list>
    </keylock>
  </resource-list>
</deadlock>
--

You can piece through it to find the <inputbuf> tag to find the queries on the Fred_Table7 that are involved, and find the loginname of Login1, but is this really how you want to consume this data?

https://blogger.googleusercontent.com/img/b/R29vZ2xl/AVvXsEgK4Lx8DWDZxjWZ9Jbqsovb7iMmL5LpfNuCcOoqdqXDHVHCAZ8vwQPRVTzjnobfpakkhY1nFdXNFysU9LTd_LZWfRAacYVSRw7jIQ3rwWh1If2FOfNGZGtbjTs2ZTO4QlxIhZ-xQE0mKcOJ/s1600/HaHaNo.jpg
A much easier way to deal with this information is in the Deadlock Graph.  


The Deadlock Graph turns the XML information show above into, well, a graph.  You can see the two transactions as the circles on the outside and the two objects involved in the rectangles in the center of the diagram.  Sometimes there are more than two transactions involved in a deadlock (beyond the scope of this post) but if there are more than two they will show up in the graph as well.  When you open the graph in SQL Server Management Studio you can hover over the transaction circle and see the underlying query and some other transaction data.

--

As mentioned above there is a trace event to return the Deadlock Graph, and you can draw it via XEvents as well with a query.

NOTE - there was a change in the way deadlock information is processed in XEvents between SQL Server 2008R2 and SQL Server 2012, so there are different scripts depending on version:

--
/*

SQL Server Deadlock Graph Extraction from Ring Buffer
SQL Server 2008/2008R2
Modified from https://www.sqlservercentral.com/Forums/1399315/System-health-extended-event-session-does-not-capture-latest-deadlocks?PageIndex=1

*/
;WITH SystemHealth

AS (
   SELECT 
      CAST ( target_data AS xml ) AS SessionXML
   FROM 
      sys.dm_xe_session_targets st
   INNER JOIN 
      sys.dm_xe_sessions s 
   ON 
      s.[address] = st.event_session_address
   WHERE 
      name = 'system_health'
)
SELECT 
   Deadlock.value ( '@timestamp', 'datetime' ) AS DeadlockDateTime
,   CAST ( Deadlock.value ( '(data/value)[1]', 'Nvarchar(max)' ) AS XML ) AS DeadlockGraph
FROM 
   SystemHealth s
CROSS APPLY 
   SessionXML.nodes ( '//RingBufferTarget/event' ) AS t (Deadlock)
WHERE 
   Deadlock.value ( '@name', 'nvarchar(128)' ) = N'xml_deadlock_report'
ORDER BY
   Deadlock.value ( '@timestamp', 'datetime' );
--
/*

SQL Server Deadlock Graph Extraction from Ring Buffer
SQL Server 2012+
Modified from https://www.red-gate.com/simple-talk/sql/database-administration/handling-deadlocks-in-sql-server/

*/
SELECT  XEvent.query('(event/data/value/deadlock)[1]') AS DeadlockGraph

FROM    ( SELECT    XEvent.query('.') AS XEvent
          FROM      ( SELECT    CAST(target_data AS XML) AS TargetData
                      FROM      sys.dm_xe_session_targets st
                                JOIN sys.dm_xe_sessions s
                                 ON s.address = st.event_session_address
                      WHERE     s.name = 'system_health'
                                AND st.target_name = 'ring_buffer'
                    ) AS Data
                    CROSS APPLY TargetData.nodes
                  ('RingBufferTarget/event[@name="xml_deadlock_report"]')
                    AS XEventData ( XEvent )
        ) AS src;   
--

Another awesome change in SQL 2012+ is that the System_Health session now writes to a file target as well as the ring buffer memory target.  This is cool because the files persist more data than can be maintained in the ring buffer, giving you more history.  Retrieving data from the XEL files requires a different query, which is set up to dynamically read the XEL files from your default LOG path, wherever it may be:

--
/*

SQL Server Deadlock Graph Extraction from XEL file target
SQL Server 2012+
http://www.sqlservercentral.com/blogs/sql-geek/2017/10/07/extracting-deadlock-information-using-system_health-extended-events/

*/

CREATE TABLE #errorlog (LogDate DATETIME , ProcessInfo VARCHAR(100), [Text] VARCHAR(MAX))
DECLARE @tag VARCHAR (MAX) , @path VARCHAR(MAX);
INSERT INTO #errorlog EXEC sp_readerrorlog;

SELECT @tag = text
FROM #errorlog 
WHERE [Text] LIKE 'Logging%MSSQL\Log%';
DROP TABLE #errorlog;
SET @path = SUBSTRING(@tag, 38, CHARINDEX('MSSQL\Log', @tag) - 29);
SELECT 

CONVERT(xml, event_data).query('/event/data/value/child::*') AS DeadlockReport,
CONVERT(xml, event_data).value('(event[@name="xml_deadlock_report"]/@timestamp)[1]', 'datetime') 
AS Execution_Time
FROM sys.fn_xe_file_target_read_file(@path + '\system_health*.xel', NULL, NULL, NULL)
WHERE OBJECT_NAME like 'xml_deadlock_report';
--

As an example, here is the output of the  ring buffer query versus the file target (XEL) query on a given server:


The file target has six times as much history as the ring buffer (in this case) - you should "always" see the same or more data in the XEL files than the ring buffer.

--

All of these scripts return an XML output like the XML shown above - it doesn't return a graph directly.

https://memegenerator.net/img/instances/71836370/say-whaaat.jpg
To get the graph is pretty straightforward - once you know how.  Open the XML document, either by clicking the link in the resultset or by copy-pasting the XML into the text editor of your choice:



Once the XML document is open, either in Management Studio or in your text editor, simply save the document as extension .XDL rather than .XML  The new file will have an icon like this: 




If you open this file in Management Studio (via double-click or Open>File in Management Studio) you will be presented with the actual Deadlock Graph as seen above, complete with ability to hover to see transaction information, etc. 

...unless you are using SQL Server 2008/2008R2 Management Studio, in which case you will see this:


Argghhhhh!

As described by Extended Events guru Jonathan Kehayias (blog/@sqlpoolboy) in a blog post here, this is an artifact of SQL 2008 Management Studio not being ready to render the deadlock output from XEvents (as opposed to the deadlock output from Trace).  As Jonathan notes there are two ways to handle this - the first way is to use an up-level Management Studio of at least version 2012, either by upgrading the local copy of Management Studio (you can download the current Management Studio that is still compatible back to 2008 from Microsoft here) or by copying the XDL file to another server with a more recent Management Studio.  The other way to open the file under SQL 2008/2008R2 is to use SentryOne's free tool Plan Explorer Pro.  I usually don't pitch company products but this is a really useful 100% free tool.

The most common answer will be the first - copy the XDL to a server with 2012+ Management Studio, and all will be well.

--

UPDATE - a friend pointed out that I had forgotten a script that does a great job shredding the Deadlock information from files, the ring buffer, or SentryOne's data collection into a useful format.  It was created by MCM/MVP Wayne Sheffield (blog/@DBAWayne) and is located here.

--

Hope this helps!


1 comment:

  1. The Oprah meme made me LOL. The bright side of deadlocks is that one gets the opportunity to kill things. ;)

    ReplyDelete