Blocked Process Report: How to Get More Value

Blocking in SQL Server is not an uncommon phenomena. Many times it is rather trivial. Sometimes, it extends beyond the realm of trivial and needs to be addressed.

How do you know when a blocked process has gone beyond the realm of trivial? What can you do to find long held blocks in SQL Server? The answer to that is actually not that simple. Why? Because there are so many methods that can help uncover blocking issues that it would be difficult to address in a single article.

However, there is a combination of tools I wish to discuss in this article that can be added to your toolbelt. These tools will help address the varying levels of blocking issues within your database environment. What are the tools? Naturally one of the tools would be Extended Events (XEvents). And it just so happens that the other tool is somewhat new to me – it is the Blocked Process Report.

Yeah yeah yeah, I said it is new to me. Truth is I haven’t used it previously because I have always used a custom built solution. That isn’t to say I wasn’t aware of the option – just hadn’t employed it. Why now? Well, to be honest it is because of the ease of use with XEvents.

For the sake of posterity, I am also adding this to the MASSIVE collection of Extended Events articles.

More Value from the Blocked Process Report

One of the big problems, I fear, with the blocked process report is that it is not easily consumed. It is somewhat kludgy and hard to read – unless you are really familiar with that kind of output. In addition, you have to twist a couple of knobs to make it work. Tweak these knobs too far and you can cause more harm than good.

Behind the scenes, the blocked process report is controlled by the deadlock detector in SQL Server. By default, the deadlock detector wakes every 5 seconds and checks for “problems”. To get the blocked process report to utilize this resource, you must configure a setting. This setting is named “blocked process threshold (s)” and is an advanced option. It is easy to adjust with a script such as the following.

SELECT *
	FROM sys.configurations c
	WHERE c.[name] LIKE 'block%';

IF EXISTS (SELECT *
FROM sys.configurations c
WHERE c.[name] LIKE 'block%'
	AND (c.value = 0
		OR c.value_in_use = 0))
BEGIN
EXECUTE sp_configure 'show advanced options', 1;
RECONFIGURE WITH OVERRIDE;

EXECUTE sp_configure 'blocked', 20; --blocked process threshold (s)
RECONFIGURE WITH OVERRIDE;
END
GO
SELECT *
	FROM sys.configurations c
	WHERE c.[name] LIKE 'block%';

SELECT *

FROM sys.configurations c

WHERE c.[name] LIKE 'block%';

IF EXISTS (SELECT *

FROM sys.configurations c

WHERE c.[name] LIKE 'block%'

AND (c.value = 0

OR c.value_in_use = 0))

BEGIN

EXECUTE sp_configure 'show advanced options', 1;

RECONFIGURE WITH OVERRIDE;

EXECUTE sp_configure 'blocked', 20; --blocked process threshold (s)

RECONFIGURE WITH OVERRIDE;

END

SELECT *

FROM sys.configurations c

WHERE c.[name] LIKE 'block%';

The previous script will evaluate the “blocked process threshold (3)” setting. If that setting is set to 0, then it will be updated (with override) to 20. This means that now the blocked process report will tap into the deadlock detector every 20 seconds and report on any blocking.

Great! Where do we find that data? That is where the power of XEvents comes into play!

XEvents Power and Blocked Processes

As previously mentioned, consuming the blocked process report is a bit of a problem. Sure, one could have used a server side trace to monitor the blocked_process_report event. That, honestly, was less than ideal. With the presence of XEvents, we have a true power tool and a remarkably ideal tool to consume and monitor the event. In the following script, I have provided the means to create an XE Session that will capture the blocked_process_report event as well as parse it into human friendly format.

Note, I have included the trace_print event in the provided session. This is to demonstrate the power of the parse script. If you have multiple events being tracked in the same session, the parse script will just bypass all of those events and only look at the blocked_process_report event.

USE master;
GO

DECLARE @XESession NVARCHAR(MAX) = 'Blocking'
	  , @DropXESQL	VARCHAR(256);

-- Create the Event Session
IF EXISTS ( SELECT *
				FROM sys.server_event_sessions ses
				WHERE ses.[name] = @XESession )
	BEGIN
		SET @DropXESQL = 'DROP EVENT SESSION ' + @XESession + '
		ON SERVER;'
		EXECUTE (@DropXESQL)
	END;

CREATE EVENT SESSION [Blocking]
	ON SERVER
	ADD EVENT sqlserver.blocked_process_report
	(ACTION (
		 package0.event_sequence
	   , sqlserver.client_app_name
	   , sqlserver.client_hostname
	   , sqlserver.database_name
	   , sqlserver.plan_handle
	   , sqlserver.session_id
	   , sqlserver.sql_text
	 )
	)
  , ADD EVENT sqlserver.trace_print
	(ACTION (
		 package0.event_sequence
	   , sqlserver.client_app_name
	   , sqlserver.client_hostname
	   , sqlserver.database_name
	   , sqlserver.plan_handle
	   , sqlserver.session_id
	   , sqlserver.sql_text
	 )
	)
	ADD TARGET package0.event_file
	(SET filename = N'C:\Database\XE\Blocking.xel')
	WITH (
		MAX_MEMORY = 4096KB
	  , EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS
	  , MAX_DISPATCH_LATENCY = 30 SECONDS
	  , MAX_EVENT_SIZE = 0KB
	  , MEMORY_PARTITION_MODE = NONE
	  , TRACK_CAUSALITY = ON
	  , STARTUP_STATE = OFF
	);
GO


IF OBJECT_ID('tempdb..#xmlprocess') IS NOT NULL
	BEGIN
		DROP TABLE #xmlprocess;
	END;

IF OBJECT_ID('tempdb..#ReportsXML') IS NOT NULL
	BEGIN
		DROP TABLE #ReportsXML;
	END;

SET NOCOUNT ON;

IF NOT EXISTS (
	SELECT	*
		FROM	sys.server_event_sessions		  es
			INNER JOIN sys.server_event_session_targets est
				ON es.event_session_id = est.event_session_id
		WHERE	est.name IN ( 'event_file' )
			AND es.name = @XESession
)
	RAISERROR(
		'Warning: The extended event session you supplied does not exist or does not have an "event_file" or "ring_buffer" target.'
	  , 10
	  , 1
	);


CREATE TABLE #ReportsXML
(
	MonitorLoopID NVARCHAR(100) NOT NULL
  , endTime DATETIME NULL
  , blocking_spid INT NOT NULL
  , blocking_ecid INT NOT NULL
  , blocked_spid INT NOT NULL
  , blocked_ecid INT NOT NULL
  , blocked_hierarchy_string AS CAST(blocked_spid AS VARCHAR(20)) + '.' + CAST(blocked_ecid AS VARCHAR(20)) + '/'
  , blocking_hierarchy_string AS CAST(blocking_spid AS VARCHAR(20)) + '.' + CAST(blocking_ecid AS VARCHAR(20)) + '/'
  , BlockedProcessReportXML XML NOT NULL
  ,
  PRIMARY KEY CLUSTERED (
	  MonitorLoopID
	, blocked_spid
	, blocked_ecid
  )
  ,
  UNIQUE NONCLUSTERED (
	  MonitorLoopID
	, blocking_spid
	, blocking_ecid
	, blocked_spid
	, blocked_ecid
  )
);

BEGIN
		DECLARE @SessionType NVARCHAR(MAX);
		DECLARE @SessionId INT;
		DECLARE @SessionTargetId INT;
		DECLARE @FilenamePattern NVARCHAR(MAX);

		SELECT	TOP (1)
				@SessionType	 = est.name
			  , @SessionId		 = est.event_session_id
			  , @SessionTargetId = est.target_id
			FROM	sys.server_event_sessions		  es
				INNER JOIN sys.server_event_session_targets est
					ON es.event_session_id = est.event_session_id
			WHERE	est.name IN ( 'event_file')
				AND es.name = @XESession;

		IF (@SessionType = 'event_file')
			BEGIN

				SELECT	@FilenamePattern = REPLACE(CAST([value] AS NVARCHAR(MAX)), '.xel', '*xel')
					FROM	sys.server_event_session_fields esf
					WHERE	esf.event_session_id = @SessionId
						AND esf.[object_id] = @SessionTargetId
						AND esf.[name] = 'filename';

				IF (@FilenamePattern NOT LIKE '%xel')
					SET @FilenamePattern += '*xel';


/* parse event data */
SELECT CAST ([t2].[event_data] AS XML) AS event_data, t2.file_offset,t2.file_name, cte1.event_session_id
	INTO #xmlprocess
	FROM ( SELECT CASE
				WHEN CAST(sesf.[value] AS NVARCHAR(128))  NOT LIKE '%xel'
					THEN REPLACE(CONVERT(NVARCHAR(128),CONVERT(NVARCHAR(128),sesf.[value]) + '.xel'),'.xel','*.xel') 
					ELSE REPLACE(CONVERT(NVARCHAR(128),sesf.[value]),'.xel','*.xel') 
				END AS targetvalue
				, ses.event_session_id
				FROM sys.server_event_sessions ses
					INNER JOIN sys.server_event_session_fields sesf
						ON ses.event_session_id = sesf.event_session_id
				WHERE sesf.[name] = 'filename'
					AND ses.[name] = @XESession
					) cte1
				OUTER APPLY sys.fn_xe_file_target_read_file(cte1.targetvalue,	NULL, NULL, NULL) t2
	WHERE t2.event_data LIKE '<event name="blocked%';

				INSERT INTO	#ReportsXML
					(
						blocked_ecid
					  , blocked_spid
					  , blocking_ecid
					  , blocking_spid
					  , MonitorLoopID
					  , BlockedProcessReportXML
					  , endTime
					)
					SELECT	bpShredded.blocked_ecid
						  , bpShredded.blocked_spid
						  , bpShredded.blocking_ecid
						  , bpShredded.blocking_spid
						  , COALESCE(
								bpShredded.MonitorLoopID, CONVERT(NVARCHAR(100), bpReports.EventDate, 120), CAST(NEWID() AS NVARCHAR(100))
							)
						  , bpReports.BlockedProcessReportXML
						  , bpReports.EventDate
						FROM	#xmlprocess AS x
							CROSS APPLY (
							SELECT	x.[event_data].value('(event/@timestamp)[1]', 'datetime')		  AS EventDate
								  , x.[event_data].query('//event/data/value/blocked-process-report') AS BlockedProcessReportXML
						) AS bpReports
							CROSS APPLY (
							SELECT	MonitorLoopID	  = BlockedProcessReportXML.value('(//@monitorLoop)[1]', 'nvarchar(100)')
								  , blocked_spid  = BlockedProcessReportXML.value(
														'(/blocked-process-report/blocked-process/process/@spid)[1]'
													  , 'int'
													)
								  , blocked_ecid  = BlockedProcessReportXML.value(
														'(/blocked-process-report/blocked-process/process/@ecid)[1]'
													  , 'int'
													)
								  , blocking_spid = BlockedProcessReportXML.value(
														'(/blocked-process-report/blocking-process/process/@spid)[1]'
													  , 'int'
													)
								  , blocking_ecid = BlockedProcessReportXML.value(
														'(/blocked-process-report/blocking-process/process/@ecid)[1]'
													  , 'int'
													)
						) AS bpShredded
						WHERE	bpShredded.blocking_spid IS NOT NULL
							AND bpShredded.blocked_spid IS NOT NULL;

			END;

	END;


WITH HeadBlockers AS (
					 SELECT blocking_spid
						  , blocking_ecid
						  , MonitorLoopID
						  , blocking_hierarchy_string
						 FROM	#ReportsXML
					 EXCEPT
					 SELECT blocked_spid
						  , blocked_ecid
						  , MonitorLoopID
						  , blocked_hierarchy_string
						 FROM	#ReportsXML
					 )
   , Hierarchy AS (
				  SELECT	MonitorLoopID
						  , blocking_spid										  AS spid
						  , blocking_ecid										  AS ecid
						  , CAST('/' + blocking_hierarchy_string AS VARCHAR(MAX)) AS chain
						  , 0													  AS level
					  FROM	HeadBlockers
				  UNION ALL
				  SELECT	irx.MonitorLoopID
						  , irx.blocked_spid
						  , irx.blocked_ecid
						  , CAST(h.chain + irx.blocked_hierarchy_string AS VARCHAR(MAX))
						  , h.level + 1
					  FROM	#ReportsXML	 irx
						  INNER JOIN Hierarchy h
							  ON irx.MonitorLoopID = h.MonitorLoopID
								  AND	irx.blocking_spid = h.spid
								  AND	irx.blocking_ecid = h.ecid
				  )
	SELECT	ISNULL(CONVERT(NVARCHAR(30), irx.endTime, 120), '') AS TraceTime
		,CASE WHEN ISNULL(CONVERT(NVARCHAR(30), irx.endTime, 120), '') = ''
			THEN 'Lead Blocker'
			ELSE 'Blocked Process'
			END AS BlockingParticipationType
		, SPACE(4 * h.[level]) + CAST(h.spid AS VARCHAR(20)) + CASE h.ecid
																   WHEN 0
																	   THEN ''
																   ELSE '(' + CAST(h.ecid AS VARCHAR(20)) + ')'
															   END	AS BlockingTree
		  , irx.BlockedProcessReportXML
		FROM	Hierarchy		  h
			LEFT OUTER JOIN #ReportsXML irx
				ON irx.MonitorLoopID = h.MonitorLoopID
					AND irx.blocked_spid = h.spid
					AND irx.blocked_ecid = h.ecid
		ORDER BY h.MonitorLoopID
			   , h.chain;

DROP TABLE #ReportsXML;
DROP TABLE #xmlprocess;

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

148

149

150

151

152

153

154

155

156

157

158

159

160

161

162

163

164

165

166

167

168

169

170

171

172

173

174

175

176

177

178

179

180

181

182

183

184

185

186

187

188

189

190

191

192

193

194

195

196

197

198

199

200

201

202

203

204

205

206

207

208

209

210

211

212

213

214

215

216

217

218

219

220

221

222

223

224

225

226

227

228

229

230

231

232

233

234

235

236

237

238

239

240

241

242

243

244

245

246

247

248

249

250

251

252

253

254

255

256

257

258

259

USE master;

DECLARE @XESession NVARCHAR(MAX) = 'Blocking'

, @DropXESQL VARCHAR(256);

-- Create the Event Session

IF EXISTS ( SELECT *

FROM sys.server_event_sessions ses

WHERE ses.[name] = @XESession )

BEGIN

SET @DropXESQL = 'DROP EVENT SESSION ' + @XESession + '

ON SERVER;'

EXECUTE (@DropXESQL)

END;

CREATE EVENT SESSION [Blocking]

ON SERVER

ADD EVENT sqlserver.blocked_process_report

(ACTION (

package0.event_sequence

, sqlserver.client_app_name

, sqlserver.client_hostname

, sqlserver.database_name

, sqlserver.plan_handle

, sqlserver.session_id

, sqlserver.sql_text

)

, ADD EVENT sqlserver.trace_print

(ACTION (

package0.event_sequence

, sqlserver.client_app_name

, sqlserver.client_hostname

, sqlserver.database_name

, sqlserver.plan_handle

, sqlserver.session_id

, sqlserver.sql_text

)

ADD TARGET package0.event_file

(SET filename = N'C:\Database\XE\Blocking.xel')

WITH (

MAX_MEMORY = 4096KB

, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS

, MAX_DISPATCH_LATENCY = 30 SECONDS

, MAX_EVENT_SIZE = 0KB

, MEMORY_PARTITION_MODE = NONE

, TRACK_CAUSALITY = ON

, STARTUP_STATE = OFF

);

IF OBJECT_ID('tempdb..#xmlprocess') IS NOT NULL

BEGIN

DROP TABLE #xmlprocess;

END;

IF OBJECT_ID('tempdb..#ReportsXML') IS NOT NULL

BEGIN

DROP TABLE #ReportsXML;

END;

SET NOCOUNT ON;

IF NOT EXISTS (

SELECT *

FROM sys.server_event_sessions es

INNER JOIN sys.server_event_session_targets est

ON es.event_session_id = est.event_session_id

WHERE est.name IN ( 'event_file' )

AND es.name = @XESession

)

RAISERROR(

'Warning: The extended event session you supplied does not exist or does not have an "event_file" or "ring_buffer" target.'

, 10

, 1

);

CREATE TABLE #ReportsXML

(

MonitorLoopID NVARCHAR(100) NOT NULL

, endTime DATETIME NULL

, blocking_spid INT NOT NULL

, blocking_ecid INT NOT NULL

, blocked_spid INT NOT NULL

, blocked_ecid INT NOT NULL

, blocked_hierarchy_string AS CAST(blocked_spid AS VARCHAR(20)) + '.' + CAST(blocked_ecid AS VARCHAR(20)) + '/'

, blocking_hierarchy_string AS CAST(blocking_spid AS VARCHAR(20)) + '.' + CAST(blocking_ecid AS VARCHAR(20)) + '/'

, BlockedProcessReportXML XML NOT NULL

PRIMARY KEY CLUSTERED (

MonitorLoopID

, blocked_spid

, blocked_ecid

)

UNIQUE NONCLUSTERED (

MonitorLoopID

, blocking_spid

, blocking_ecid

, blocked_spid

, blocked_ecid

)

);

BEGIN

DECLARE @SessionType NVARCHAR(MAX);

DECLARE @SessionId INT;

DECLARE @SessionTargetId INT;

DECLARE @FilenamePattern NVARCHAR(MAX);

SELECT TOP