Capturing Blocked Queries

Microsoft SQL Server

In a previous post, I presented a solution for monitoring and logging long running queries in SQL Server. In this post I’ll show an extended version of that solution that also sends an email when a request has been blocked for more than 20 seconds.

Blocked Queries

Be sure to read the the original post about long running queries before implementing the solution outlined here.

To a DBA, notifications on blocked queries in a database can be a very useful tool in a proactive work trying to enhance the user experience. In the blog post mentioned above, I showed how to capture and store T-SQL queries that run for longer than 20 seconds.

That solution can be extended to also send an email whenever a long running query is caused by a lock. Most locks are resolved automatically after a while, but in some cases DBA intervention can be necessary. It is also very valuable troubleshooting information for the DBA. This extended solution will send the email when the total blocked_wait_time exceeds 20 seconds.

Note that the goal with this solution, and the one for long running queries, is to catch blocks that affect the user experience. Therefore, there is a rather long list of wait types that are not monitored, meaning not all blocks will be reported. Naturally, the list of excluded wait types can be changed as you see fit.

To use the solution you need to change the @profile_name and @recipients parameters for the sp_send_dbmail procedure:

EXEC msdb.dbo.sp_send_dbmail
	@profile_name = <YourEmailProfile>,
	@recipients = <Recipients>,
	@subject = 'Blocked queries detected!',
	@body = @MAIL_BODY,
	@body_format='HTML'

Follow the instructions in the long running queries post, but use this T-SQL instead (remember to change parameters on sp_send_dbmail):

SET QUOTED_IDENTIFIER ON
SET NOCOUNT ON

DECLARE @StartMonitoringAfterSeconds INT = 20, @MAIL_BODY NVARCHAR(4000)

IF (SELECT OBJECT_ID('#TLind_IGNORED_WAIT_TYPES')) IS NULL BEGIN
	CREATE TABLE #TLind_IGNORED_WAIT_TYPES
		(
			WaitType NVARCHAR(60) NOT NULL
		)
	--http://www.sqlskills.com/blogs/paul/wait-statistics-or-please-tell-me-where-it-hurts/
	INSERT #TLind_IGNORED_WAIT_TYPES (WaitType)
	VALUES
	('BROKER_EVENTHANDLER'),
	('BROKER_RECEIVE_WAITFOR'),
	('BROKER_TASK_STOP'),
	('BROKER_TO_FLUSH'),
	('BROKER_TRANSMITTER'),
	('CHECKPOINT_QUEUE'),
	('CHKPT'),
	('CLR_AUTO_EVENT'),
	('CLR_MANUAL_EVENT'),
	('CLR_SEMAPHORE'),
	('DBMIRROR_DBM_EVENT'),
	('DBMIRROR_EVENTS_QUEUE'),
	('DBMIRROR_WORKER_QUEUE'),
	('DBMIRRORING_CMD'),
	('DIRTY_PAGE_POLL'),
	('DISPATCHER_QUEUE_SEMAPHORE'),
	('EXECSYNC'),
	('FSAGENT'),
	('FT_IFTS_SCHEDULER_IDLE_WAIT'),
	('FT_IFTSHC_MUTEX'),
	('HADR_CLUSAPI_CALL'),
	('HADR_FILESTREAM_IOMGR_IOCOMPLETION'),
	('HADR_LOGCAPTURE_WAIT'),
	('HADR_NOTIFICATION_DEQUEUE'),
	('HADR_TIMER_TASK'),
	('HADR_WORK_QUEUE'),
	('KSOURCE_WAKEUP'),
	('LAZYWRITER_SLEEP'),
	('LOGMGR_QUEUE'),
	('ONDEMAND_TASK_QUEUE'),
	('PWAIT_ALL_COMPONENTS_INITIALIZED'),
	('QDS_PERSIST_TASK_MAIN_LOOP_SLEEP'),
	('QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP'),
	('REQUEST_FOR_DEADLOCK_SEARCH'),
	('RESOURCE_QUEUE'),
	('SERVER_IDLE_CHECK'),
	('SLEEP_BPOOL_FLUSH'),
	('SLEEP_DBSTARTUP'),
	('SLEEP_DCOMSTARTUP'),
	('SLEEP_MASTERDBREADY'),
	('SLEEP_MASTERMDREADY'),
	('SLEEP_MASTERUPGRADED'),
	('SLEEP_MSDBSTARTUP'),
	('SLEEP_SYSTEMTASK'),
	('SLEEP_TASK'),
	('SLEEP_TEMPDBSTARTUP'),
	('SNI_HTTP_ACCEPT'),
	('SP_SERVER_DIAGNOSTICS_SLEEP'),
	('SQLTRACE_BUFFER_FLUSH'),
	('SQLTRACE_INCREMENTAL_FLUSH_SLEEP'),
	('SQLTRACE_WAIT_ENTRIES'),
	('WAIT_FOR_RESULTS'),
	('WAITFOR'),
	('WAITFOR_TASKSHUTDOWN'),
	('WAIT_XTP_HOST_WAIT'),
	('WAIT_XTP_OFFLINE_CKPT_NEW_LOG'),
	('WAIT_XTP_CKPT_CLOSE'),
	('XE_DISPATCHER_JOIN'),
	('XE_DISPATCHER_WAIT'),
	('XE_TIMER_EVENT')
END

SELECT
	R.session_id
	,R.request_id
	,R.start_time
	,CAST('1900-01-01' AS DATETIME2) AS completed_time
	,S.[host_name]
	,S.[program_name]
	,S.login_name
	,R.[status]
	,R.command
	,R.database_id
	,R.wait_type
	,R.wait_time / 1000 AS blocked_wait_time_sec
	,R.last_wait_type
	,R.wait_resource
	,R.total_elapsed_time / 1000 AS total_elapsed_time_sec
	,ST.text
	,R.blocking_session_id
	,S_B.[host_name] AS blocking_host_name
	,S_B.[program_name] AS blocking_program_name
	,S_B.login_name AS blocking_login_name
	,ST_B.text AS blocking_text
INTO
	#TLind_LONG_RUNNING
FROM
	sys.dm_exec_requests R
CROSS APPLY
    sys.dm_exec_sql_text(R.sql_handle) AS ST
JOIN
	sys.dm_exec_sessions S
ON
	R.session_id = S.session_id
LEFT OUTER JOIN
	sys.dm_exec_connections C
ON
	R.blocking_session_id = C.session_id
OUTER APPLY
    sys.dm_exec_sql_text(C.most_recent_sql_handle) AS ST_B
LEFT OUTER JOIN
	sys.dm_exec_sessions S_B
ON
	R.blocking_session_id = S_B.session_id
WHERE
	R.[status] NOT IN ('background', 'sleeping')
AND
	R.wait_type NOT IN (SELECT WaitType FROM #TLind_IGNORED_WAIT_TYPES)
AND
	R.session_id > 50
AND
	R.session_id <> @@spid
AND
	(R.total_elapsed_time / 1000) > (@StartMonitoringAfterSeconds)


IF EXISTS (SELECT * FROM #TLind_LONG_RUNNING) BEGIN

	CREATE UNIQUE CLUSTERED INDEX TLind_LONG_RUNNING_CLU ON #TLind_LONG_RUNNING(session_id, request_id, start_time) WITH IGNORE_DUP_KEY

	CREATE TABLE #TLind_BLOCKED_QUERIES
		(
			session_id SMALLINT NOT NULL
			,request_id INT NOT NULL
			,start_time DATETIME NOT NULL
			,mail_sent BIT DEFAULT(0) NOT NULL
		)

	CREATE UNIQUE CLUSTERED INDEX TLind_BLOCKED_QUERIES_CLU ON #TLind_BLOCKED_QUERIES(session_id, request_id, start_time) WITH IGNORE_DUP_KEY

	WHILE EXISTS(SELECT * FROM #TLind_LONG_RUNNING WHERE completed_time = '1900-01-01') BEGIN

		/*********************************
		BLOCKED QUERY ACTION
		*********************************/
		INSERT #TLind_BLOCKED_QUERIES (session_id,request_id,start_time)
		SELECT session_id, request_id, start_time
		FROM #TLind_LONG_RUNNING
		WHERE blocked_wait_time_sec >= 20
		AND blocking_session_id > 50
		AND blocking_session_id <> session_id

		IF @@ROWCOUNT > 0 BEGIN
			SET @MAIL_BODY = '<table border="1" align="center" cellpadding="2" cellspacing="0" style="color:black;font-family:consolas;text-align:center;font-size:8.0pt;">' +
				'<tr>
				<th>Blocked SPID</th>
				<th>Blocked Login</th>
				<th>Blocked Statement</th>
				<th>Blocked Statement Time</th>
				<th>blocked_wait_time_sec</th>
				<th>Blocking SPID</th>
				<th>Blocking Login</th>
				<th>Blocking Statement</th>'

			SELECT
				@MAIL_BODY = @MAIL_BODY +
					'<tr>' +
					'<td>' + CAST(BQ.session_id AS NVARCHAR(5)) + '</td>' +
					'<td>' + LR.login_name + '</td>' +
					'<td>' + CAST(ISNULL(LR.text, '...') AS NVARCHAR(100)) + '</td>' +
					'<td>' + CONVERT(NVARCHAR(23), LR.start_time, 121) + '</td>' +
					'<td>' + CAST(LR.blocked_wait_time_sec AS NVARCHAR(10)) + '</td>' +
					'<td>' + CAST(ISNULL(LR.blocking_session_id, 0) AS NVARCHAR(5)) + '</td>' +
					'<td>' + ISNULL(LR.blocking_login_name, '...') + '</td>' +
					'<td>' + CAST(ISNULL(LR.blocking_text, '...') AS NVARCHAR(100)) + '</td>'
			FROM
				#TLind_BLOCKED_QUERIES BQ
			JOIN
				#TLind_LONG_RUNNING LR
			ON
				BQ.session_id = LR.session_id
			AND
				BQ.request_id = LR.request_id
			AND
				BQ.start_time = LR.start_time
			WHERE
				BQ.mail_sent = 0
			ORDER BY
				LR.start_time DESC

			UPDATE #TLind_BLOCKED_QUERIES SET mail_sent = 0

			EXEC msdb.dbo.sp_send_dbmail
				@profile_name = <YourEmailProfile>,
				@recipients = <Recipients>,
				@subject = 'Blocked queries detected!',
				@body = @MAIL_BODY,
				@body_format='HTML'

		END

		WAITFOR DELAY '00:00:01'

		UPDATE
			#TLind_LONG_RUNNING
		SET
			completed_time = CASE WHEN R.session_id IS NULL AND LR.completed_time = '1900-01-01' THEN GETDATE() ELSE LR.completed_time END
			,[host_name] = COALESCE(S.[host_name], LR.[host_name])
			,[program_name] = COALESCE(S.[program_name], LR.[program_name])
			,login_name = COALESCE(S.[login_name], LR.[login_name])
			,[status] = COALESCE(R.[status], LR.[status])
			,command = COALESCE(R.command, LR.command)
			,database_id = COALESCE(R.database_id, LR.database_id)
			,wait_type = COALESCE(R.wait_type, LR.wait_type)
			,blocked_wait_time_sec = COALESCE(R.wait_time / 1000, LR.blocked_wait_time_sec)
			,last_wait_type = COALESCE(R.last_wait_type, LR.last_wait_type)
			,wait_resource = COALESCE(R.wait_resource, LR.wait_resource)
			,total_elapsed_time_sec = COALESCE(R.total_elapsed_time / 1000, LR.total_elapsed_time_sec)
			,text = COALESCE(ST.text, LR.text)
			,blocking_session_id = COALESCE(NULLIF(R.blocking_session_id, 0), LR.blocking_session_id)
			,blocking_host_name = COALESCE(S_B.[host_name], LR.blocking_host_name)
			,blocking_program_name = COALESCE(S_B.[program_name], LR.blocking_program_name)
			,blocking_login_name = COALESCE(S_B.login_name, LR.blocking_login_name)
			,blocking_text = COALESCE(ST_B.text, LR.blocking_text)
		FROM
			#TLind_LONG_RUNNING LR
		LEFT OUTER JOIN
			sys.dm_exec_requests R
		ON
			LR.session_id = R.session_id
		AND
			LR.request_id = R.request_id
		AND
			LR.start_time = R.start_time
		OUTER APPLY
			sys.dm_exec_sql_text(R.sql_handle) AS ST
		LEFT OUTER JOIN
			sys.dm_exec_sessions S
		ON
			R.session_id = S.session_id
		LEFT OUTER JOIN
			sys.dm_exec_connections C
		ON
			R.blocking_session_id = C.session_id
		OUTER APPLY
			sys.dm_exec_sql_text(C.most_recent_sql_handle) AS ST_B
		LEFT OUTER JOIN
			sys.dm_exec_sessions S_B
		ON
			R.blocking_session_id = S_B.session_id

		INSERT
			#TLind_LONG_RUNNING
		SELECT
			R.session_id
			,R.request_id
			,R.start_time
			,CAST('1900-01-01' AS DATETIME2) AS completed_time
			,S.[host_name]
			,S.[program_name]
			,S.login_name
			,R.[status]
			,R.command
			,R.database_id
			,R.wait_type
			,R.wait_time / 1000 AS blocked_wait_time_sec
			,R.last_wait_type
			,R.wait_resource
			,R.total_elapsed_time / 1000 AS total_elapsed_time_sec
			,ST.text
			,R.blocking_session_id
			,S_B.[host_name] AS blocking_host_name
			,S_B.[program_name] AS blocking_program_name
			,S_B.login_name AS blocking_login_name
			,ST_B.text AS blocking_text
		FROM
			sys.dm_exec_requests R
		CROSS APPLY
			sys.dm_exec_sql_text(R.sql_handle) AS ST
		JOIN
			sys.dm_exec_sessions S
		ON
			R.session_id = S.session_id
		LEFT OUTER JOIN
			sys.dm_exec_connections C
		ON
			R.blocking_session_id = C.session_id
		OUTER APPLY
			sys.dm_exec_sql_text(C.most_recent_sql_handle) AS ST_B
		LEFT OUTER JOIN
			sys.dm_exec_sessions S_B
		ON
			R.blocking_session_id = S_B.session_id
		WHERE
			R.[status] NOT IN ('background', 'sleeping')
		AND
			R.wait_type NOT IN (SELECT WaitType FROM #TLind_IGNORED_WAIT_TYPES)
		AND
			R.session_id > 50
		AND
			R.session_id <> @@spid
		AND
			(R.total_elapsed_time / 1000) > (@StartMonitoringAfterSeconds)
	END

	IF (SELECT OBJECT_ID('TLind_LONG_RUNNING')) IS NULL BEGIN
		CREATE TABLE TLind_LONG_RUNNING
			(
				session_id SMALLINT NOT NULL
				,request_id INT NOT NULL
				,start_time DATETIME NOT NULL
				,completed_time DATETIME2 NOT NULL
				,[host_name] NVARCHAR(128) NULL
				,[program_name] NVARCHAR(128) NULL
				,login_name NVARCHAR(128) NOT NULL
				,[status] NVARCHAR(30) NOT NULL
				,command NVARCHAR(32) NOT NULL
				,database_id SMALLINT NOT NULL
				,wait_type NVARCHAR(60) NULL
				,blocked_wait_time_sec INT NOT NULL
				,last_wait_type NVARCHAR(60) NOT NULL
				,wait_resource NVARCHAR(256) NOT NULL
				,total_elapsed_time_sec INT NOT NULL
				,text NVARCHAR(MAX) NULL
				,blocking_session_id SMALLINT NULL
				,blocking_host_name NVARCHAR(128) NULL
				,blocking_program_name NVARCHAR(128) NULL
				,blocking_login_name NVARCHAR(128) NULL
				,blocking_text NVARCHAR(MAX) NULL
			)
	END

	INSERT TLind_LONG_RUNNING
	SELECT * FROM #TLind_LONG_RUNNING

END

DROP TABLE #TLind_LONG_RUNNING
IF (SELECT OBJECT_ID('#TLind_BLOCKED_QUERIES')) IS NOT NULL BEGIN
	DROP TABLE #TLind_BLOCKED_QUERIES
END

If you want to do something else instead of sending an email when a blocked query is encountered, just change the highlighted code above to something else.

As always, make sure to test the solution before running it in a production environment.

Leave a Reply

Required fields are marked *.