Capturing and Interpreting SQL Deadlocks

One of the most frustrating events when troubleshooting problems is database deadlocking. There are a variety of ways for deadlocking to occur, and you want find what is causing yours specifically, but it is hard to do so. The following information will provide some better detail on how to collect and interpret database deadlocks in the Altiris environment.

Three basic strategies can be used for gathering deadlock information.

1. Perfmon "Number of Deadlocks/sec" counter
2. Set and inspect the output of the trace flag 1204, found in the SQL logs
3. Use SQL Trace/Profiler's deadlock events.

Perfmon's " Number of Deadlocks/sec" Counter

The Perfmon counter "Number of Deadlocks/sec" counter is useful in measuring the frequency of deadlocking. This counter is found in SQLServer: Locks, and has many instances to choose from. You can list the deadlocks by table, by database, or by some of the other options available. It's also useful in multi-user testing to determine the minimum number of users required to reproduce deadlocks. However, it does not show individual deadlocks, it only shows that some deadlocking is occurring.

Figure 1. PERFMON's Number of Deadlocks/sec counter object

Click to view.

The 1204 Trace Flag

The output of the trace flag 1204 can be invaluable in diagnosing a deadlock. It is often used in combination with the 3605 flag as well. You set it in Query Analyzer:

DBCC TRACEON(3605, 1204)

Or

DBCC TRACEON(3605)
DBCC TRACEON(1204)

The output of the flag will be sent to the SQL Server error log whenever SQL Server encounters a deadlock. You may find it useful to make a SQL Agent job execute these statements at startup so that the SQL Server error log will always report any deadlocks.

Interpreting the output of the trace flag 1204 can be challenging. Figure 2 shows a sample output and what some of the entries mean.

Figure 2. You can inspect the output of the trace flag 1204 to gather detailed information about a deadlock.

Click to view.

When you look at the deadlock in Figure 2, the first statement under node 1 outlines as follows:

KEY: 7:1977058079:1 (f600d547433a)

7: - This refers to Database number 7

1977058079 - This is the object id

:1 - Is the clustered index on the authors table. Since it's a key lock, this reflects a row lock on a clustered index.

f600d547433a - This is the hash of clustered index key value

Other lines include other important data. For example, the spid numbers are important when cross-referencing to SQL Trace data. You can see Displaying Locking Information and Troubleshooting Deadlocks in Books Online for more information.

What the output of the trace flag 1204 shows is the input buffer of the blocked request statements, and that the locks held at the grant stage. Unfortunately, it does not show the statements initiating the grant stage locks. Also, the input buffer may be incomplete or truncated.

To get the full transaction history for each spid involved in the deadlock we need to use SQL Profiler and SQL Trace.

Using SQL Profiler to Gather Deadlock Information

SQL Profiler has two important event types that you can use for deadlocks: deadlock and deadlock chain. However, if you supplement your trace with some additional events, you'll get a more readable output. You can select the following events, and shown in Figures 3 and 4.

• Cursors: CursorExecute, CursorPrepare
• Errors and Warnings: Attentions and Exceptions
• Locks: Lock:Deadlock and Lock:Deadlock Chain
• Stored Procedures: RPC:Completed, RPC:Starting, SP:StmtCompleted, SP:StmtStarted
• Transactions: SQL Transaction
• TSQL: SQL:BatchCompleted, SQL:BatchStarting, SQL:StmtCompleted, SQL:StmtStarting

Figure 3. SQL Profiler Event Configuration

Click to view.

Figure 4. SQL Profiler Event Configuration

Click to view.

These event settings capture the following data:

Cursors events - Capture server side cursor queries

Errors and Warnings:

Attentions - Capture timeouts

Exceptions - Capture SQL Server error events (including error 1205)

Stored Procedures:

RPC counters capture stored procedures executed using SQL Server's RPC interface

SP: events capture stored procedures executed as direct SQL.

Transactions:

SQL Transaction - This event shows when the thread begins a transaction

TSQL:

All events capture individual SQL statements

This will end up providing a lot of data, and you may not want to use all these counters unless you're zeroing in on an event that you want a lot of data about.

Then you can add the following data columns:

• EventClass
• EventSubclass
• Spid
• IntegerData
• Mode
• StartTime
• TextData
• DatabaseID
• IndexID
• HostName
• ObjectID
• TransactionID
• Severity

These are shown in Figure 5:

Figure 5. SQL Profiler Data Column Configuration

Click to view.

The majority of the data columns are self explanatory. The EventSubclass and TransactionID columns work with the SQL Transaction event.

When you view a deadlock in SQL Profiler with the above events and columns, your output will look something like that in Figure 6.

Figure 6. SQL Profiler will show you the deadlock event and matching spids.

Click to view.

SQL Profiler shows you the statements involved in the deadlock. The deadlock victim will have a statement starting but not ending, if you chose the proper events. You'll also see the beginning and end of each spid's transaction, so you can use SQL Profiler to reproduce each deadlocking spid's transaction history. This can help to produce a reproduction scenario for the deadlock.

Unfortunately, SQL Profiler does not show the statements gaining the initial locks at the grant stage because SQL Profiler does not show locking information. You can choose to add the locks events, but the resulting amount of information is voluminous. The trace flag 1204 shows what those locks were, but it does not show what statements were granted the locks.

A combination of SQL Profiler and the trace flag 1204 output is the best way to gain information about complex and subtle deadlocks. You can often spot simple deadlocks from either tool and diagnose them quickly.