SQL Server Blocking and Deadlocks: How to Investigate

2018-05-12 · mssql, performance, locking

"The application is hanging" is the most common call I get, and about half the time the database isn't slow at all. One session is holding a lock and dozens of others are waiting for it. Blocking is normal in small doses; it's a problem when a transaction stays open for minutes because of an uncommitted batch, a missing index, or an app that opened a transaction and then waited for user input. Deadlocks are the special case where two sessions block each other and SQL Server kills one.

My routine: find the head blocker, see what it's running, and capture deadlocks after the fact so they can be fixed properly.

Who is blocking whom right now

The quickest query, using only built-in DMVs:

SELECT r.session_id, r.blocking_session_id, r.wait_type, r.wait_time / 1000 AS wait_s,
       r.wait_resource, s.login_name, s.host_name, s.program_name,
       DB_NAME(r.database_id) AS database_name,
       SUBSTRING(t.text, (r.statement_start_offset / 2) + 1,
           ((CASE r.statement_end_offset WHEN -1 THEN DATALENGTH(t.text)
             ELSE r.statement_end_offset END - r.statement_start_offset) / 2) + 1) AS running_statement
FROM sys.dm_exec_requests r
JOIN sys.dm_exec_sessions s ON s.session_id = r.session_id
CROSS APPLY sys.dm_exec_sql_text(r.sql_handle) t
WHERE r.blocking_session_id <> 0
ORDER BY r.wait_time DESC;

blocking_session_id tells you who each waiter is waiting on. Follow the chain until you reach a session that is not itself blocked; that is the head blocker.

The head blocker

The head blocker is often not in sys.dm_exec_requests because it is idle: it has an open transaction and is doing nothing. Check it with:

SELECT s.session_id, s.status, s.login_name, s.host_name, s.program_name,
       s.last_request_start_time, s.last_request_end_time,
       s.open_transaction_count, c.most_recent_sql_handle
FROM sys.dm_exec_sessions s
JOIN sys.dm_exec_connections c ON c.session_id = s.session_id
WHERE s.session_id = 74;   -- the head blocker

SELECT text FROM sys.dm_exec_sql_text(0x0200...);  -- most_recent_sql_handle from above

status = sleeping with open_transaction_count > 0 is the signature of an application that started a transaction and never committed. The most recent SQL text shows the last statement it ran, which is usually enough to identify the code path.

If you use Adam Machanic's sp_WhoIsActive, all of this is one call:

EXEC sp_WhoIsActive @find_block_leaders = 1, @sort_order = '[blocked_session_count] DESC';

To kill or not to kill

I only kill when the head blocker is an idle session with an old open transaction and I can't reach the owner:

KILL 74;

Rolling back a large transaction can take as long as it took to run. Check progress with KILL 74 WITH STATUSONLY.

Catching the overnight blocking

To catch blocking that happens overnight, enable the blocked process threshold (in seconds) and record the reports with an Extended Events session:

EXEC sp_configure 'show advanced options', 1; RECONFIGURE;
EXEC sp_configure 'blocked process threshold (s)', 20; RECONFIGURE;

CREATE EVENT SESSION [BlockedProcess] ON SERVER
ADD EVENT sqlserver.blocked_process_report
ADD TARGET package0.event_file (SET filename = N'D:\XE\BlockedProcess.xel', max_file_size = 50, max_rollover_files = 4)
WITH (STARTUP_STATE = ON);
ALTER EVENT SESSION [BlockedProcess] ON SERVER STATE = START;

Each report contains the blocked and blocking statements plus the lock resource, as XML.

Deadlocks live in system_health

SQL Server 2012 and later already record every deadlock in the built-in system_health Extended Events session, so you rarely need trace flag 1222 anymore. Pull the recent deadlock graphs:

;WITH ring AS (
    SELECT CAST(xet.target_data AS xml) AS target_data
    FROM sys.dm_xe_session_targets xet
    JOIN sys.dm_xe_sessions xe ON xe.address = xet.event_session_address
    WHERE xe.name = 'system_health' AND xet.target_name = 'ring_buffer')
SELECT x.value('@timestamp', 'datetime2') AS event_time,
       x.query('data/value/deadlock') AS deadlock_graph
FROM ring
CROSS APPLY target_data.nodes('RingBufferTarget/event[@name="xml_deadlock_report"]') AS t(x)
ORDER BY event_time DESC;

Right-click a deadlock_graph cell in SSMS, save it as .xdl, and open the file in SSMS to see the graphical version. The ring buffer keeps only a few hours; the system_health event files under the Log directory go back further:

SELECT CAST(event_data AS xml).value('(event/@timestamp)[1]', 'datetime2') AS event_time,
       CAST(event_data AS xml).query('event/data/value/deadlock') AS deadlock_graph
FROM sys.fn_xe_file_target_read_file('system_health*.xel', NULL, NULL, NULL)
WHERE object_name = 'xml_deadlock_report';

Reading the graph

In the XML, the <process-list> section shows each session, its isolation level, the statement it was running (inputbuf) and the object it was waiting on. The <resource-list> section shows the locks: keylock for an index key, pagelock, objectlock for a whole table. The process with id matching the victim attribute at the top is the one that was killed with error 1205.

The two patterns behind most deadlocks:

Two procedures update the same tables in opposite order. Fix: always touch tables in the same order.
A missing index turns a targeted UPDATE into a scan that takes locks on far more rows than needed. Fix: add the index; the deadlock disappears because the lock footprint shrinks.

Is it fixed?

After a code change or a new index, watch the deadlock count over time:

SELECT cntr_value AS deadlocks_since_restart
FROM sys.dm_os_performance_counters
WHERE object_name LIKE '%Locks%' AND counter_name = 'Number of Deadlocks/sec' AND instance_name = '_Total';

The counter is cumulative despite the name. If it stops increasing, the fix worked.

Errors you'll meet

Transaction (Process ID 63) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction. (Error 1205.) This is what the application sees. The application should retry; the DBA should pull the graph from system_health.
Lock request time out period exceeded. (Error 1222.) A session with SET LOCK_TIMEOUT gave up waiting. Same investigation as blocking.
blocked_process_report never fires. The threshold is 0 (disabled) or the blocking lasts less than the threshold. Check sp_configure 'blocked process threshold (s)'.
sys.dm_exec_sql_text returns NULL for the head blocker. The session is idle; use most_recent_sql_handle from sys.dm_exec_connections instead of sql_handle from sys.dm_exec_requests.

The fix is usually boring: a shorter transaction, a consistent table order, or one missing index.