Archive for the ‘Extended Events’ Category

We had a deadlock on a SQL 2008 r2 server but did not have the deadlock trace flags running. Luckily we now have Extended Events available for deadlocks.

To investigate I ran this code (taken from a post By Jonathan Kehayias
http://www.sqlservercentral.com/articles/deadlock/65658/)

SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
select CAST(
REPLACE(
REPLACE(XEventData.XEvent.value(‘(data/value)[1]’, ‘varchar(max)’),

”, ”),
”,”)
as xml) as DeadlockGraph
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 name = ‘system_health’) AS Data
CROSS APPLY TargetData.nodes (‘//RingBufferTarget/event’) AS XEventData (XEvent)
where XEventData.XEvent.value(‘@name’, ‘varchar(4000)’) = ‘xml_deadlock_report’;

Which gave be a deadlock graph. Actually it gave a malformed deadlock graph because we need to patch the server (https://connect.microsoft.com/SQLServer/feedback/details/404168/invalid-xml-in-extended-events-xml-deadlock-report-output)

To fix this I replaced the final </deadlock> with </victim-list> although you may not need to do this.

The graph gave me these bits of information (the info for both was the same (other than SPids etc) because it was the same stored proc running twice which cause the deadlock.))

<process-list>
<process id=”process50934c8″ taskpriority=”0″ logused=”568″ waitresource=”PAGE: 9:4:8453″ waittime=”2822″ ownerId=”73869146″
transactionname=”INSERT” lasttranstarted=”2012-05-04T18:15:41.003″ XDES=”0x17d4aa3b0″ lockMode=”IX” schedulerid=”12″
kpid=”5132″ status=”background” spid=”35″ sbid=”0″ ecid=”0″ priority=”0″ trancount=”2″>
<executionStack>
<frame procname=”” line=”120″ stmtstart=”9448″ stmtend=”11092″ sqlhandle=”0x030009002a854154312dff0045a000000100000000000000″ />
<frame procname=”” line=”1″ stmtstart=”102″ sqlhandle=”0x010009009c37861ef05ac675050000000000000000000000″ />
<frame procname=”” line=”1″ sqlhandle=”0x0400ff7fbe80662601000000000000000000000000000000″ />
<frame procname=”” line=”78″ stmtstart=”4870″ stmtend=”5260″ sqlhandle=”0x030009000c8ae7465a93010145a000000100000000000000″ />
<frame procname=”” line=”34″ stmtstart=”1774″ stmtend=”1888″ sqlhandle=”0x030009009b87944d7ab3ff00489f00000100000000000000″ />
</executionStack>
<inputbuf />
</process>

I took the sql handles and ran them here:

SELECT *
FRoM
sys.dm_exec_sql_text(0x030009002a854154312dff0045a000000100000000000000);
SELECT *
FRoM sys.dm_exec_sql_text(0x01000900953c3516b086df9f020000000000000000000000);
SELECT *
FRoM sys.dm_exec_sql_text(0x0400ff7fbe80662601000000000000000000000000000000);
SELECT *
FRoM sys.dm_exec_sql_text(0x030009000c8ae7465a93010145a000000100000000000000);
SELECT *
FRoM sys.dm_exec_sql_text(0x030009009b87944d7ab3ff00489f00000100000000000000);

It then listed three different stored procs. Only had an Insert candidate but I wanted to confirm it.

Back to the graph:
<pagelock fileid=”4″ pageid=”8453″ dbid=”9″ objectname=”” id=”locked7e4900″ mode=”S” associatedObjectId=”72057594040614912″>

From this I can get the object that was blocked, either by this:

dbcc traceon (3604); –needs to be on to display the results of dbcc page
dbcc page ( 9, 4, 8453 , 0);

Partial result set:

name object_id type type_desc
RealNameWithheld 133575514 U USER_TABLE

I confirmed this result by running this:

SELECT OBJECT_NAME([object_id])
FROM sys.partitions
WHERE partition_id = 72057594040614912;

Using the associatedObjectId from the Deadlock graph

The result: SameTableName

Back to the grap to look at this:
<pagelock fileid=”4″ pageid=”8453″ dbid=”9″ objectname=”” id=”locked7e4900″ mode=”S” associatedObjectId=”72057594040614912″>
<owner-list>
<owner id=”process3ce748″ mode=”S” />
</owner-list>
<waiter-list>
<waiter id=”process50934c8″ mode=”IX” requestType=”convert” />
</waiter-list>
</pagelock>
<pagelock fileid=”4″ pageid=”8453″ dbid=”9″ objectname=”” id=”locked7e4900″ mode=”S” associatedObjectId=”72057594040614912″>
<owner-list>
<owner id=”process50934c8″ mode=”S” />
</owner-list>
<waiter-list>
<waiter id=”process3ce748″ mode=”IX” requestType=”convert” />
</waiter-list>
</pagelock>

In the stored procedure there was this code:

INSERT INTO RealNameWithheld (Column Listing)
SELECT A mix of variables and column names
FROM RealNameWithheld
WHERE request_id = ISNULL(@LastRequestID, -1)

The table being inserted into is the same as the table being used in the Select. The Select is asking for the shared lock (S) the insert is asking for an exclusive lock (IX – intent exclusive).

Both procedures ran at almost the same time – 3 milliseconds apart – and so both acquired a shared lock at almost the same time. They both then tried to acquire the exclusive lock but to do that they needed to wait for the other to relinquish its shared lock. A normal Select would eventually return its results and drop the lock. In this case it wouldn’t drop the lock as it is waiting to escalate it.

This problem doesn’t occur often so we can either leave it as it is. To fix it we could add a query hint to the SELECT part of the statement – with (TabLock). With this hint the first query to reach the table gains an exclusive lock on the table. The subsequent query will then wait.

In other circumstances we could use (NoLock) but that would be too risky on this table where the data is being updated frequently.

A work around: First select into a temporary table. Then use the temporary table to insert back into the original. This will be slightly slower but won’t cause the deadlock.