Deadlock and Trace Flags 1204 and 1222

Posted on Posted in DBA, Performance Tuning No Comments Tagged with ,
Download PDF

When you are looking for deadlocks there are, like most things in SQL Server, more than one way to find the deadlocks. This article is specifically focused on using the SQL Server ERRORLOG file located in the LOG directory for the SQL instance. If you used the defaults on SQL Server 2012, this log would be at this location:

C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL\Log\ERRORLOG

For SQL Server 2014 it would be here:

C:\Program Files\Microsoft SQL Server\MSSQL12.MSSQLSERVER\MSSQL\Log\ERRORLOG

and in similar locations for other versions of SQL Server.

 

What is a Deadlock?

deadLock

A deadlock is a specific case in SQL Server and other databases where, in the simple case of two transactions, the first transaction gets stuck waiting on blocking from the second transaction, and the second transaction gets stuck waiting on blocking for the first transaction.

Imagine traffic so jammed up that one lane of travel is blocking another lane of travel, and vice versa. The deadlock in SQL Server is similar to this, but instead of traffic being blocked, it is queries and transactions being blocked.

Eventually in traffic when cars are blocking, one will give up and back out, and the other will be allowed to drive through. The one that backs out is known as the deadlock victim.

When one query is chosen as the deadlock victim, it looks something like this:

You have been chosen as a deadlock victim

 

By default, when a deadlock is encountered nothing is logged to the ERRORLOG file in SQL Server, however this can be changed with a couple of trace flags.

Trace Flag 1204

Basic information added into the ERRORLOG file when a deadlock is encountered. This flag was originally introduced in SQL Server 2000.

Here is an example from the ERROR LOG FILE with TRACE FLAG 1204 turned on. The section below is for a single deadlock.

2015-04-22 17:00:42.06 spid57 DBCC TRACEON 1204, server process ID (SPID) 57. This is an informational message only; no user action is required.
2015-04-22 17:01:21.53 spid5s Deadlock encountered …. Printing deadlock information
2015-04-22 17:01:21.54 spid5s Wait-for graph
2015-04-22 17:01:21.54 spid5s
2015-04-22 17:01:21.54 spid5s Node:1

2015-04-22 17:01:21.54 spid5s KEY: 14:72057594039042048 (8194443284a0) CleanCnt:2 Mode:X Flags: 0x1
2015-04-22 17:01:21.54 spid5s Grant List 0:
2015-04-22 17:01:21.54 spid5s Owner:0x00000000FA436540 Mode: X Flg:0x40 Ref:0 Life:02000000 SPID:57 ECID:0 XactLockInfo: 0x00000000F9CB76E8
2015-04-22 17:01:21.54 spid5s SPID: 57 ECID: 0 Statement Type: UPDATE Line #: 9
2015-04-22 17:01:21.54 spid5s Input Buf: Language Event:
BEGIN TRANSACTION;
UPDATE [dbo].[Departments]
SET [Name] = ‘xxx’;
WAITFOR DELAY ’00:00:30′;

UPDATE [dbo].[Resources]
SET [Name] = ‘yyy’;

ROLLBACK TRANSACTION;

2015-04-22 17:01:21.54 spid5s Requested by:
2015-04-22 17:01:21.54 spid5s ResType:LockOwner Stype:’OR’Xdes:0x00000000FF470D28 Mode: U SPID:58 BatchID:0 ECID:0 TaskProxy:(0x00000000F3E38608) Value:0xfa436580 Cost:(0/992)
2015-04-22 17:01:21.54 spid5s
2015-04-22 17:01:21.54 spid5s Node:2

2015-04-22 17:01:21.54 spid5s KEY: 14:72057594039107584 (8194443284a0) CleanCnt:2 Mode:X Flags: 0x1
2015-04-22 17:01:21.54 spid5s Grant List 2:
2015-04-22 17:01:21.54 spid5s Owner:0x00000000FA436680 Mode: X Flg:0x40 Ref:0 Life:02000000 SPID:58 ECID:0 XactLockInfo: 0x00000000FF470D68
2015-04-22 17:01:21.54 spid5s SPID: 58 ECID: 0 Statement Type: UPDATE Line #: 8
2015-04-22 17:01:21.54 spid5s Input Buf: Language Event: BEGIN TRANSACTION;
UPDATE [dbo].[Resources]
SET [Name] = ‘abc’;
WAITFOR DELAY ’00:00:30′;

UPDATE [dbo].[Departments]
SET [Name] = ‘def’;

2015-04-22 17:01:21.54 spid5s Requested by:
2015-04-22 17:01:21.54 spid5s ResType:LockOwner Stype:’OR’Xdes:0x00000000F9CB76A8 Mode: U SPID:57 BatchID:0 ECID:0 TaskProxy:(0x00000000F266E608) Value:0xfa435bc0 Cost:(0/992)
2015-04-22 17:01:21.54 spid5s
2015-04-22 17:01:21.54 spid5s Victim Resource Owner:
2015-04-22 17:01:21.54 spid5s ResType:LockOwner Stype:’OR’Xdes:0x00000000FF470D28 Mode: U SPID:58 BatchID:0 ECID:0 TaskProxy:(0x00000000F3E38608) Value:0xfa436580 Cost:(0/992)

 

 

Trace Flag 1222

More details that 1204.

Here is the same deadlock as above with TRACE FLAG 12014 turned off, and TRACE FLAG 1222 turned on.

2015-04-22 17:04:44.58 spid57 DBCC TRACEOFF 1204, server process ID (SPID) 57. This is an informational message only; no user action is required.
2015-04-22 17:04:44.58 spid57 DBCC TRACEON 1222, server process ID (SPID) 57. This is an informational message only; no user action is required.
2015-04-22 17:05:16.83 spid34s deadlock-list
2015-04-22 17:05:16.83 spid34s deadlock victim=processff035498
2015-04-22 17:05:16.83 spid34s process-list
2015-04-22 17:05:16.83 spid34s process id=processff035498 taskpriority=0 logused=992 waitresource=KEY: 14:72057594039042048 (8194443284a0) waittime=2890 ownerId=10178 transactionname=user_transaction lasttranstarted=2015-04-22T17:04:53.937 XDES=0xff470d28 lockMode=U schedulerid=5 kpid=3472 status=suspended spid=58 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2015-04-22T17:04:53.937 lastbatchcompleted=2015-04-22T17:04:53.937 lastattention=1900-01-01T00:00:00.937 clientapp=Microsoft SQL Server Management Studio – Query hostname=XPS8500 hostpid=1996 loginname=sa isolationlevel=read committed (2) xactid=10178 currentdb=14 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2015-04-22 17:05:16.83 spid34s executionStack
2015-04-22 17:05:16.83 spid34s frame procname=adhoc line=8 stmtstart=36 sqlhandle=0x020000004b55b71427e224488d8ae60084ba0ba2a74d7b0b0000000000000000000000000000000000000000
2015-04-22 17:05:16.83 spid34s UPDATE [dbo].[Departments] set [Name] = @1
2015-04-22 17:05:16.83 spid34s frame procname=adhoc line=8 stmtstart=204 sqlhandle=0x02000000897eda2351193104cd6f512569b50520ba99bf450000000000000000000000000000000000000000
2015-04-22 17:05:16.83 spid34s UPDATE [dbo].[Departments]
2015-04-22 17:05:16.83 spid34s SET [Name] = ‘def’;
2015-04-22 17:05:16.83 spid34s inputbuf
2015-04-22 17:05:16.83 spid34s BEGIN TRANSACTION;
2015-04-22 17:05:16.83 spid34s UPDATE [dbo].[Resources]
2015-04-22 17:05:16.83 spid34s SET [Name] = ‘abc’;
2015-04-22 17:05:16.83 spid34s WAITFOR DELAY ’00:00:20′;
2015-04-22 17:05:16.83 spid34s UPDATE [dbo].[Departments]
2015-04-22 17:05:16.83 spid34s SET [Name] = ‘def’;
2015-04-22 17:05:16.83 spid34s process id=processf313e188 taskpriority=0 logused=992 waitresource=KEY: 14:72057594039107584 (8194443284a0) waittime=4891 ownerId=10085 transactionname=user_transaction lasttranstarted=2015-04-22T17:04:51.920 XDES=0xf9cb76a8 lockMode=U schedulerid=1 kpid=2340 status=suspended spid=57 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2015-04-22T17:04:51.920 lastbatchcompleted=2015-04-22T17:04:51.920 lastattention=1900-01-01T00:00:00.920 clientapp=Microsoft SQL Server Management Studio – Query hostname=XPS8500 hostpid=1996 loginname=sa isolationlevel=read committed (2) xactid=10085 currentdb=14 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2015-04-22 17:05:16.83 spid34s executionStack
2015-04-22 17:05:16.83 spid34s frame procname=adhoc line=9 stmtstart=36 sqlhandle=0x020000006ece2303088612d98662d952df74dfa3844a3b620000000000000000000000000000000000000000
2015-04-22 17:05:16.83 spid34s UPDATE [dbo].[Resources] set [Name] = @1
2015-04-22 17:05:16.83 spid34s frame procname=adhoc line=9 stmtstart=214 stmtend=314 sqlhandle=0x020000006230041404e58acce4fe1fde7e8d7c189e98ec2f0000000000000000000000000000000000000000
2015-04-22 17:05:16.83 spid34s UPDATE [dbo].[Resources]
2015-04-22 17:05:16.83 spid34s SET [Name] = ‘yyy’;
2015-04-22 17:05:16.83 spid34s inputbuf
2015-04-22 17:05:16.83 spid34s BEGIN TRANSACTION;
2015-04-22 17:05:16.83 spid34s UPDATE [dbo].[Departments]
2015-04-22 17:05:16.83 spid34s SET [Name] = ‘xxx’;
2015-04-22 17:05:16.83 spid34s WAITFOR DELAY ’00:00:20′;
2015-04-22 17:05:16.83 spid34s UPDATE [dbo].[Resources]
2015-04-22 17:05:16.83 spid34s SET [Name] = ‘yyy’;
2015-04-22 17:05:16.83 spid34s ROLLBACK TRANSACTION;
2015-04-22 17:05:16.83 spid34s resource-list
2015-04-22 17:05:16.83 spid34s keylock hobtid=72057594039042048 dbid=14 objectname=DeadlockBlock.dbo.Departments indexname=PK_Departments id=lockff6d3800 mode=X associatedObjectId=72057594039042048
2015-04-22 17:05:16.83 spid34s owner-list
2015-04-22 17:05:16.83 spid34s owner id=processf313e188 mode=X
2015-04-22 17:05:16.83 spid34s waiter-list
2015-04-22 17:05:16.83 spid34s waiter id=processff035498 mode=U requestType=wait
2015-04-22 17:05:16.83 spid34s keylock hobtid=72057594039107584 dbid=14 objectname=DeadlockBlock.dbo.Resources indexname=PK_Resource id=lockff6de700 mode=X associatedObjectId=72057594039107584
2015-04-22 17:05:16.83 spid34s owner-list
2015-04-22 17:05:16.83 spid34s owner id=processff035498 mode=X
2015-04-22 17:05:16.83 spid34s waiter-list
2015-04-22 17:05:16.83 spid34s waiter id=processf313e188 mode=U requestType=wait

 

Trace Flag 1204 and 1222 Combined

Even more information, with both trace flags turned on.

2015-04-22 17:07:21.31 spid57 DBCC TRACEON 1204, server process ID (SPID) 57. This is an informational message only; no user action is required.
2015-04-22 17:07:21.32 spid57 DBCC TRACEON 1222, server process ID (SPID) 57. This is an informational message only; no user action is required.
2015-04-22 17:07:49.55 spid5s Deadlock encountered …. Printing deadlock information
2015-04-22 17:07:49.55 spid5s Wait-for graph
2015-04-22 17:07:49.55 spid5s
2015-04-22 17:07:49.55 spid5s Node:1

2015-04-22 17:07:49.55 spid5s KEY: 14:72057594039042048 (8194443284a0) CleanCnt:2 Mode:X Flags: 0x1
2015-04-22 17:07:49.55 spid5s Grant List 0:
2015-04-22 17:07:49.55 spid5s Owner:0x00000000FA41BD80 Mode: X Flg:0x40 Ref:0 Life:02000000 SPID:57 ECID:0 XactLockInfo: 0x00000000F9CB76E8
2015-04-22 17:07:49.55 spid5s SPID: 57 ECID: 0 Statement Type: UPDATE Line #: 9
2015-04-22 17:07:49.55 spid5s Input Buf: Language Event:
BEGIN TRANSACTION;
UPDATE [dbo].[Departments]
SET [Name] = ‘xxx’;
WAITFOR DELAY ’00:00:20′;

UPDATE [dbo].[Resources]
SET [Name] = ‘yyy’;

ROLLBACK TRANSACTION;

2015-04-22 17:07:49.55 spid5s Requested by:
2015-04-22 17:07:49.55 spid5s ResType:LockOwner Stype:’OR’Xdes:0x00000000FF470D28 Mode: U SPID:58 BatchID:0 ECID:0 TaskProxy:(0x00000000F3E38608) Value:0xfa436580 Cost:(0/992)
2015-04-22 17:07:49.55 spid5s
2015-04-22 17:07:49.55 spid5s Node:2

2015-04-22 17:07:49.55 spid5s KEY: 14:72057594039107584 (8194443284a0) CleanCnt:2 Mode:X Flags: 0x1
2015-04-22 17:07:49.55 spid5s Grant List 2:
2015-04-22 17:07:49.55 spid5s Owner:0x00000000FA436680 Mode: X Flg:0x40 Ref:0 Life:02000000 SPID:58 ECID:0 XactLockInfo: 0x00000000FF470D68
2015-04-22 17:07:49.55 spid5s SPID: 58 ECID: 0 Statement Type: UPDATE Line #: 8
2015-04-22 17:07:49.55 spid5s Input Buf: Language Event: BEGIN TRANSACTION;
UPDATE [dbo].[Resources]
SET [Name] = ‘abc’;
WAITFOR DELAY ’00:00:20′;

UPDATE [dbo].[Departments]
SET [Name] = ‘def’;

2015-04-22 17:07:49.55 spid5s Requested by:
2015-04-22 17:07:49.55 spid5s ResType:LockOwner Stype:’OR’Xdes:0x00000000F9CB76A8 Mode: U SPID:57 BatchID:0 ECID:0 TaskProxy:(0x00000000F266E608) Value:0xfa41b8c0 Cost:(0/992)
2015-04-22 17:07:49.56 spid5s
2015-04-22 17:07:49.56 spid5s Victim Resource Owner:
2015-04-22 17:07:49.56 spid5s ResType:LockOwner Stype:’OR’Xdes:0x00000000FF470D28 Mode: U SPID:58 BatchID:0 ECID:0 TaskProxy:(0x00000000F3E38608) Value:0xfa436580 Cost:(0/992)
2015-04-22 17:07:49.56 spid24s deadlock-list
2015-04-22 17:07:49.56 spid24s deadlock victim=processff035498
2015-04-22 17:07:49.56 spid24s process-list
2015-04-22 17:07:49.56 spid24s process id=processff035498 taskpriority=0 logused=992 waitresource=KEY: 14:72057594039042048 (8194443284a0) waittime=1578 ownerId=12506 transactionname=user_transaction lasttranstarted=2015-04-22T17:07:27.977 XDES=0xff470d28 lockMode=U schedulerid=5 kpid=3472 status=suspended spid=58 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2015-04-22T17:07:27.973 lastbatchcompleted=2015-04-22T17:07:27.973 lastattention=1900-01-01T00:00:00.973 clientapp=Microsoft SQL Server Management Studio – Query hostname=XPS8500 hostpid=1996 loginname=sa isolationlevel=read committed (2) xactid=12506 currentdb=14 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2015-04-22 17:07:49.56 spid24s executionStack
2015-04-22 17:07:49.56 spid24s frame procname=adhoc line=8 stmtstart=36 sqlhandle=0x020000004b55b71427e224488d8ae60084ba0ba2a74d7b0b0000000000000000000000000000000000000000
2015-04-22 17:07:49.56 spid24s UPDATE [dbo].[Departments] set [Name] = @1
2015-04-22 17:07:49.56 spid24s frame procname=adhoc line=8 stmtstart=204 sqlhandle=0x02000000897eda2351193104cd6f512569b50520ba99bf450000000000000000000000000000000000000000
2015-04-22 17:07:49.56 spid24s UPDATE [dbo].[Departments]
2015-04-22 17:07:49.56 spid24s SET [Name] = ‘def’;
2015-04-22 17:07:49.56 spid24s inputbuf
2015-04-22 17:07:49.56 spid24s BEGIN TRANSACTION;
2015-04-22 17:07:49.56 spid24s UPDATE [dbo].[Resources]
2015-04-22 17:07:49.56 spid24s SET [Name] = ‘abc’;
2015-04-22 17:07:49.56 spid24s WAITFOR DELAY ’00:00:20′;
2015-04-22 17:07:49.56 spid24s UPDATE [dbo].[Departments]
2015-04-22 17:07:49.56 spid24s SET [Name] = ‘def’;
2015-04-22 17:07:49.56 spid24s process id=processf313e558 taskpriority=0 logused=992 waitresource=KEY: 14:72057594039107584 (8194443284a0) waittime=3240 ownerId=12481 transactionname=user_transaction lasttranstarted=2015-04-22T17:07:26.317 XDES=0xf9cb76a8 lockMode=U schedulerid=1 kpid=3736 status=suspended spid=57 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2015-04-22T17:07:26.317 lastbatchcompleted=2015-04-22T17:07:26.317 lastattention=1900-01-01T00:00:00.317 clientapp=Microsoft SQL Server Management Studio – Query hostname=XPS8500 hostpid=1996 loginname=sa isolationlevel=read committed (2) xactid=12481 currentdb=14 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2015-04-22 17:07:49.56 spid24s executionStack
2015-04-22 17:07:49.56 spid24s frame procname=adhoc line=9 stmtstart=36 sqlhandle=0x020000006ece2303088612d98662d952df74dfa3844a3b620000000000000000000000000000000000000000
2015-04-22 17:07:49.56 spid24s UPDATE [dbo].[Resources] set [Name] = @1
2015-04-22 17:07:49.56 spid24s frame procname=adhoc line=9 stmtstart=214 stmtend=314 sqlhandle=0x020000007ecfa92c7c563a5b17a5fa429dc44b70198d45fd0000000000000000000000000000000000000000
2015-04-22 17:07:49.56 spid24s UPDATE [dbo].[Resources]
2015-04-22 17:07:49.56 spid24s SET [Name] = ‘yyy’;
2015-04-22 17:07:49.56 spid24s inputbuf
2015-04-22 17:07:49.56 spid24s BEGIN TRANSACTION;
2015-04-22 17:07:49.56 spid24s UPDATE [dbo].[Departments]
2015-04-22 17:07:49.56 spid24s SET [Name] = ‘xxx’;
2015-04-22 17:07:49.56 spid24s WAITFOR DELAY ’00:00:20′;
2015-04-22 17:07:49.56 spid24s UPDATE [dbo].[Resources]
2015-04-22 17:07:49.56 spid24s SET [Name] = ‘yyy’;
2015-04-22 17:07:49.56 spid24s ROLLBACK TRANSACTION;
2015-04-22 17:07:49.56 spid24s resource-list
2015-04-22 17:07:49.56 spid24s keylock hobtid=72057594039042048 dbid=14 objectname=DeadlockBlock.dbo.Departments indexname=PK_Departments id=lockff6b3c00 mode=X associatedObjectId=72057594039042048
2015-04-22 17:07:49.56 spid24s owner-list
2015-04-22 17:07:49.56 spid24s owner id=processf313e558 mode=X
2015-04-22 17:07:49.56 spid24s waiter-list
2015-04-22 17:07:49.56 spid24s waiter id=processff035498 mode=U requestType=wait
2015-04-22 17:07:49.56 spid24s keylock hobtid=72057594039107584 dbid=14 objectname=DeadlockBlock.dbo.Resources indexname=PK_Resource id=lockff6e8d00 mode=X associatedObjectId=72057594039107584
2015-04-22 17:07:49.56 spid24s owner-list
2015-04-22 17:07:49.56 spid24s owner id=processff035498 mode=X
2015-04-22 17:07:49.56 spid24s waiter-list
2015-04-22 17:07:49.56 spid24s waiter id=processf313e558 mode=U requestType=wait

 

Here is the example code that I used to create the deadlocks.

USE Master;
GO

IF EXISTS(SELECT name
            FROM sys.databases
		   WHERE name = 'DeadlockBlock')
BEGIN
	ALTER DATABASE [DeadlockBlock]
	  SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
	DROP DATABASE [DeadlockBlock];
END
CREATE DATABASE [DeadlockBlock];
GO

USE DeadlockBlock;

-- create a couple of tables to use in the deadlock sample
CREATE TABLE [dbo].[Departments]
(
	[id] [int] IDENTITY(1,1) NOT NULL,
	[Name] [varchar](30) NULL,
 CONSTRAINT [PK_Departments] PRIMARY KEY CLUSTERED ([id] ASC)
);

CREATE TABLE [dbo].[Resources]
(
	[id] [int] IDENTITY(1,1) NOT NULL,
	[Name] [varchar](30) NULL,
 CONSTRAINT [PK_Resource] PRIMARY KEY CLUSTERED ([id] ASC)
);

-- Insert some data into each of the tables.
--  Not much here, each table will certainly fit into a single page.
INSERT INTO [dbo].[Departments]
           ([Name])
     VALUES
           ('One'),('Two'),('Three'),('Four'),('Five'),('Six'),('Seven');
GO
INSERT INTO [dbo].[Resources]
           ([Name])
     VALUES
           ('One'),('Two'),('Three'),('Four'),('Five'),('Six'),('Seven');

Then I ran the following in one query window in SSMS.

USE DeadlockBlock;
GO

BEGIN TRANSACTION;
UPDATE [dbo].[Departments]
   SET [Name] = 'xxx';

WAITFOR DELAY '00:00:20';

UPDATE [dbo].[Resources]
  SET [Name] = 'yyy';

ROLLBACK TRANSACTION;

and this query was run in a second query window in SSMS.

USE DeadlockBlock;
GO
BEGIN TRANSACTION;
UPDATE [dbo].[Resources]
  SET [Name] = 'abc';

WAITFOR DELAY '00:00:20';

UPDATE [dbo].[Departments]
   SET [Name] = 'def';

ROLLBACK TRANSACTION;

The WAITFOR DELAY was used to simulate a long running load. Waiting 20 seconds allowed for plenty of time to kick off the second query in the second query window.

The first time it as run with neither 1204 or 1222 enabled.
Next I enabled just trace flag 1204.

DBCC TRACEOFF (1222,-1);
DBCC TRACEON  (1204,-1);

Followed by just 1222.

DBCC TRACEOFF (1204,-1);
DBCC TRACEON  (1222,-1);

Then both of them together.

DBCC TRACEON  (1204,-1);
DBCC TRACEON  (1222,-1);

Note the -1 param on DBCC TRACEON or DBCC TRACEOFF globally across all sessions. Warning: don’t do this on a production server.

What was observed in SSMS was identical in all situations, the thing that did vary was the contents of the ERROR log file after a deadlock was encountered.

These DBCC Trace Flags 1204 and 1222 are great ways to track down deadlocks on your SQL Server, however they are not the only way, for instance the Database Health Monitor application can be used to find currently blocking deadlocked queries on your SQL Server.

See Also:

 

More from Stedman Solutions:

SteveStedman5
Steve and the team at Stedman Solutions are here for all your SQL Server needs.
Contact us today for your free 30 minute consultation..
We are ready to help!

Related Posts

Leave a Reply

Your email address will not be published. Required fields are marked *

*