Don’t be a victim… Log your SQL Server deadlocks

Quite often there are situations in which you are aware that deadlocks are happening in your SQL Server database, but you are lacking the information required to fix them.

What you need under these circumstances is an automated way of tracking the locks and logging them.

In this article, I demonstrate a simple way to set up lock monitoring for your database. The logs which are produced will show the exact SQL queries which were running at the time of each deadlock, providing you with the information you need in order to determine the root cause.

Deadlock example

So how do we recognise when our application has encountered a deadlock?

Transaction (Process ID 74) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

This is the kind of error message you might expect to see when your application encounters a deadlock.

In very simple terms, a deadlock will occur if query ‘A’ is waiting for a particular resource that query ‘B’ is using, while at the same time query ‘B’ is waiting for a resource that query ‘A’ is currently holding on to. Eventually, a timeout will be reached. One of the queries will succeed and the other query will fail with a deadlock error.

The monitoring which we’ll configure below will help you to track down this kind of issue and will also allow you to see generally where there is contention/locking occurring in your database.

Setting things up

Before we begin, you’ll need an Edition of SQL Server which includes the SQL Server Agent, such as the Standard or Developer Edition. You’ll also need to have SQL Server Management Studio installed.

First of all, open up SQL Server Management Studio and connect to the database instance which you need to configure the logging for.

Note that I’m using version 18 of SQL Server Management Studio and I’m connecting to a SQL Server 2019 instance. However, the steps should be very similar for earlier versions.

After you have logged into your database instance, right-click on the ‘SQL Server Agent’ node, select ‘New’, then select ‘Job…’.

Creating a new SQL Server Agent Job
Creating a new SQL Server Agent Job

A ‘New Job’ dialog will appear.

The ‘General’ section of the dialog allows you to configure some basic settings for the Job.

Configuring the General settings of the Job
Configuring the General settings of the Job

Enter a sensible name into the ‘Name’ field e.g. ‘SQL Lock Monitoring’. You can leave everything else at the default values unless there’s something in particular that you want to change.

Next, go to the ‘Steps’ section on the left-hand side and click the ‘New…’ button.

A ‘New Job Step’ dialog will open up.

Configuring the General settings of the 'Run SQL' Job Step
Configuring the General settings of the ‘Run SQL’ Job Step

Enter a name into the ‘Step name’ field e.g. ‘Run SQL’.

Set the ‘Type’ to be ‘Transact-SQL script (T-SQL)’.

Leave ‘Run as’ empty.

The ‘Database’ should default to ‘master’.

Paste the following SQL into the ‘Command’ textbox.

-- Output any blocked/blocking processes.
 
SET NOCOUNT ON
GO
 
IF EXISTS (SELECT name
           FROM   tempdb..sysobjects
           WHERE  name = '#BlockedProcesses')
	DROP TABLE #BlockedProcesses
GO
 
CREATE TABLE #BlockedProcesses
(
    BlockedSPID   INT,
    BlockedStatus CHAR(10)
)
GO
 
INSERT INTO #BlockedProcesses
	SELECT DISTINCT spid, 'BLOCKED'
	FROM   master..sysprocesses
	WHERE  blocked <> 0
UNION
	SELECT DISTINCT blocked, 'BLOCKING'
	FROM   master..sysprocesses
	WHERE  blocked <> 0
 
DECLARE @LogBlockedSPID   INT 
DECLARE @LogBlockedStatus CHAR(10)
 
SELECT TOP 1 @LogBlockedSPID = BlockedSPID, @LogBlockedStatus = BlockedStatus
FROM #BlockedProcesses
 
WHILE(@@ROWCOUNT > 0)
    BEGIN
 
        PRINT 'DBCC Results for SPID ' + CAST(@LogBlockedSPID AS VARCHAR(5)) + ' (' + RTRIM(@LogBlockedStatus) + ')'
        PRINT '----------------------------------'
        PRINT ''
        DBCC INPUTBUFFER(@LogBlockedSPID)
	PRINT ''
 
        SELECT TOP 1 @LogBlockedSPID = BlockedSPID, @LogBlockedStatus = BlockedStatus
        FROM     #BlockedProcesses
        WHERE    BlockedSPID > @LogBlockedSPID
        ORDER BY BlockedSPID
 
    END

The SQL creates a temporary table and inserts the details of all SQL Server processes which are currently blocked into it. The details of each blocked process are then selected and printed. When we’ve completed the setup, our Job will capture the output of the PRINT command and log it to a file.

Moving on, within the same ‘New Job Step’ dialog, go to the ‘Advanced’ tab.

Configuring the Advanced settings of the 'Run SQL' Job Step
Configuring the Advanced settings of the ‘Run SQL’ Job Step

Choose an ‘Output file’ location and select the ‘Append output to existing file’ option.

Everything else can be left as default e.g. ‘Run as user’ can be left empty etc.

Click ‘OK’.

Back on the ‘New Job’ dialog go to the ‘Schedules’ section and click on the ‘New…’ button.

Configuring the Job Schedule settings
Configuring the Job Schedule settings

Enter a name into the ‘Name’ field e.g. ‘Log Every 10 Seconds’.

Leave the ‘Schedule type’ as ‘Recurring’.

Under the ‘Frequency’ heading, set ‘Occurs’ to ‘Daily’.

Under the ‘Daily frequency’ heading, change the ‘Occurs every’ value to ’10’ and set the interval combo-box to ‘second(s)’.

If desired, you can also configure the ‘Starting at’ and ‘Ending at’ fields to match the period during which the database is active. This will help to minimise the size of the log files.

Click ‘OK’.

Lastly, back on the ‘New Job’ dialog, click ‘OK’ again to complete the Job setup.

Note that after completing the setup the Job will start immediately and will append its output to the specified log file every 10 seconds (you can adjust this to your desired frequency). Don’t forget to disable the Job whenever you are finished testing.

Output inspection

So what does the output of the Job look like?

You should expect to see entries that look similar to the example below in the log file which is generated.

Job 'SQL Lock Monitoring' : Step 1, 'Run SQL' : Began Executing 2019-06-29 08:58:40

Job 'SQL Lock Monitoring' : Step 1, 'Run SQL' : Began Executing 2019-06-29 08:58:51

Job 'SQL Lock Monitoring' : Step 1, 'Run SQL' : Began Executing 2019-06-29 08:59:00

Job 'SQL Lock Monitoring' : Step 1, 'Run SQL' : Began Executing 2019-06-29 08:59:10

Job 'SQL Lock Monitoring' : Step 1, 'Run SQL' : Began Executing 2019-06-29 08:59:20

Job 'SQL Lock Monitoring' : Step 1, 'Run SQL' : Began Executing 2019-06-29 08:59:30

DBCC Results for SPID 55 (BLOCKED) [SQLSTATE 01000]
---------------------------------- [SQLSTATE 01000]
EventType Parameters EventInfo 
--------- ---------- -----------------------------
RPC Event 0 sys.sp_MSenumchangesdirect;1
DBCC execution completed. If DBCC printed error messages, contact your system administrator. [SQLSTATE 01000]
DBCC Results for SPID 57 (BLOCKED) [SQLSTATE 01000]
---------------------------------- [SQLSTATE 01000]
EventType Parameters EventInfo 
--------- ---------- -----------------------------
RPC Event 0 sys.sp_MSenumchangesdirect;1
DBCC execution completed. If DBCC printed error messages, contact your system administrator. [SQLSTATE 01000]
DBCC Results for SPID 75 (BLOCKING) [SQLSTATE 01000]
---------------------------------- [SQLSTATE 01000]
EventType Parameters EventInfo 
-------------- ---------- --------------------------------------------------------------------------------------------------------------------------------------------
Language Event 0 (@Balance float)UPDATE Accounts SET Balance = @Balance WHERE ID = 234 SELECT SCOPE_IDENTITY() AS NEWID
DBCC execution completed. If DBCC printed error messages, contact your system administrator. [SQLSTATE 01000]
DBCC Results for SPID 116 (BLOCKED) [SQLSTATE 01000]
---------------------------------- [SQLSTATE 01000]
EventType Parameters EventInfo 
--------- ---------- --------------------------
RPC Event 0 sys.sp_MSmakegeneration;1
DBCC execution completed. If DBCC printed error messages, contact your system administrator. [SQLSTATE 01000]
DBCC Results for SPID 119 (BLOCKED) [SQLSTATE 01000]
---------------------------------- [SQLSTATE 01000]
EventType Parameters EventInfo 
--------- ---------- --------------------------
RPC Event 0 sys.sp_MSsetlastsentgen;1
DBCC execution completed. If DBCC printed error messages, contact your system administrator. [SQLSTATE 01000]

The logging is minimal until blocked processes are encountered. However, whenever blocked processes are detected, the output provides lots of detail in regards to what is going on with locking in the database.

Note that the output displays whatever locks were ongoing at the time of the Job execution and not all locks will result in a deadlock. Therefore, you’ll need to correlate the output with your own application logs. It is usually best to gather deadlock exception timestamps from your application logs and then see what locks were happening at the same time to see which queries actually caused the deadlock.

We can see in the above example (from the emboldened text) that the sys.sp_MSenumchangesdirect stored procedure call is blocking the UPDATE Accounts SET Balance... SQL query.

Being able to see the stored procedure name and the actual SQL query text for both the blocking process and the blocked process is very useful for determining the root cause.

Unfortunately, empty PRINT commands are ignored when outputting to a log file, however, this is a minor inconvenience given the insight we are able to obtain from the logs.

Wrapping up

I trust that you will find the monitoring Job useful and that it will help you to identify and fix any deadlock errors you’ve been encountering.

It is much simpler than some of the alternative approaches which involve more complex procedures such as turning on trace flags and running the Profiler or using Extended Events.

If you need to roll this out across more than one server, the ‘Script Job as’ feature within SQL Server Management Studio will allow you to create a SQL script which can be used to recreate it elsewhere. Don’t forget to update the @owner_login_name and @output_file_name within the generated SQL script before executing it.

You can find the SQL from this blog post on my SQL Server Scripts GitHub repository.

 

Comments

This site uses Akismet to reduce spam. Learn how your comment data is processed.