Analyzing easily the blocked process report

Which DBA has not yet face a performance problem issued by several blocked processes? In reality, I’m sure a very little number of them. Troubleshooting a blocked issue scenario is not always easy and may require to use some useful tools to simplify this hard task. A couple of months ago, I had to deal this scenario at one of my customer. During some specific periods in the business day, he noticed that its application slowed down and he asked to me how to solve this issue.

Fortunately, SQL Server provides a useful feature to catch blocked processes. We have just to configure the “blocked process threshold (s)” server option. There are plenty of blogs that explain how to play with this parameter. So I let you perform your own investigation by using your favourite search engine.

Having a blocked process report is useful but often in such situation, there are a lot of processes that sometimes blocked each other’s and we have to find out among this can of worms the real responsible. So, my main concern was the following: how to extract information from the blocked process report and how to correlate all blocked processes together. After some investigation I found a useful script written by Michael J S Swart here. Usually I prefer to write my own script but I didn’t had the time and I had to admit this script met perfectly my need. The original version provides the blocked hierarchy and the XML view of the issue. It’s not so bad because we have all the information to troubleshoot our issue. However, my modification consists to change this XM view by adding useful information in tabular format to make the reading of the final result easier. Here the modified version of the script:

use AdventureWorks2012;
go

if exists (select 1 from sys.procedures where name = N'sp_blocked_process_report_viewer_dbi')
	drop procedure [dbo].[sp_blocked_process_report_viewer_dbi];
go

CREATE PROCEDURE [dbo].[sp_blocked_process_report_viewer_dbi]
(
       @Trace nvarchar(max),
       @Type varchar(10) = 'FILE'
)
 
AS
 
SET NOCOUNT ON
 
-- Validate @Type
IF (@Type NOT IN('FILE', 'TABLE', 'XMLFILE'))
       RAISERROR ('The @Type parameter must be ''FILE'', ''TABLE'' or ''XMLFILE''', 11, 1)
 
IF (@Trace LIKE '%.trc' AND @Type <> 'FILE')
       RAISERROR ('Warning: You specified a .trc trace. You should also specify @Type = ''FILE''', 10, 1)
 
IF (@Trace LIKE '%.xml' AND @Type <> 'XMLFILE')
       RAISERROR ('Warning: You specified a .xml trace. You should also specify @Type = ''XMLFILE''', 10, 1)
    
 
CREATE TABLE #ReportsXML
(
       monitorloop nvarchar(100) NOT NULL,
       endTime datetime NULL,
       blocking_spid INT NOT NULL,
       blocking_ecid INT NOT NULL,
       blocking_bfinput NVARCHAR(MAX),
       blocked_spid INT NOT NULL,
       blocked_ecid INT NOT NULL,
       blocked_bfinput NVARCHAR(MAX),
       blocked_waitime BIGINT,
       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)) + '/',
       bpReportXml xml not null,
       primary key clustered (monitorloop, blocked_spid, blocked_ecid),
       unique nonclustered (monitorloop, blocking_spid, blocking_ecid, blocked_spid, blocked_ecid)
)
 
DECLARE @SQL NVARCHAR(max);
DECLARE @TableSource nvarchar(max);
 
-- define source for table
IF (@Type = 'TABLE')
BEGIN
       -- everything input by users get quoted
       SET @TableSource = ISNULL(QUOTENAME(PARSENAME(@Trace,4)) + N'.', '')
             + ISNULL(QUOTENAME(PARSENAME(@Trace,3)) + N'.', '')
             + ISNULL(QUOTENAME(PARSENAME(@Trace,2)) + N'.', '')
             + QUOTENAME(PARSENAME(@Trace,1));
END
 
-- define source for trc file
IF (@Type = 'FILE')
BEGIN
       SET @TableSource = N'sys.fn_trace_gettable(N' + QUOTENAME(@Trace, '''') + ', -1)';
END
 
-- load table or file
IF (@Type IN('TABLE', 'FILE'))
BEGIN
       SET @SQL = N'    
             INSERT #ReportsXML(blocked_ecid, blocked_spid, blocked_bfinput , blocking_ecid, blocking_spid,
                                blocking_bfinput, blocked_waitime, monitorloop, bpReportXml,endTime)
             SELECT
                    blocked_ecid,
                    blocked_spid,
                    blocked_inputbuffer,
                    blocking_ecid,
                    blocking_spid,
                    blocking_inputbuffer,
                blocked_waitime,
                    COALESCE(monitorloop, CONVERT(nvarchar(100), endTime, 120), ''unknown''),
                    bpReportXml,
                    EndTime
             FROM ' + @TableSource + N'
             CROSS APPLY (
                    SELECT CAST(TextData as xml)
                    ) AS bpReports(bpReportXml)
             CROSS APPLY (
                    SELECT
monitorloop = bpReportXml.value(''(//@monitorLoop)[1]'', ''nvarchar(100)''),
blocked_spid = bpReportXml.value(''(/blocked-process-report/blocked-process/process/@spid)[1]'', ''int''),
blocked_ecid = bpReportXml.value(''(/blocked-process-report/blocked-process/process/@ecid)[1]'', ''int''),
                           blocked_inputbuffer = bpReportXml.value(''(/blocked-process-report/blocked-process/process/inputbuf/text())[1]'', ''nvarchar(max)''),
blocking_spid = bpReportXml.value(''(/blocked-process-report/blocking-process/process/@spid)[1]'', ''int''),
blocking_ecid = bpReportXml.value(''(/blocked-process-report/blocking-process/process/@ecid)[1]'', ''int''),
                           blocking_inputbuffer = bpReportXml.value(''(/blocked-process-report/blocking-process/process/inputbuf/text())[1]'', ''nvarchar(max)''),
blocked_waitime = bpReportXml.value(''(/blocked-process-report/blocked-process/process/@waittime)[1]'', ''bigint'')
                    ) AS bpShredded
             WHERE EventClass = 137';
          
       EXEC (@SQL);
END
 
IF (@Type = 'XMLFILE')
BEGIN
       CREATE TABLE #TraceXML(
             id int identity primary key,
             ReportXML xml NOT NULL  
       )
    
       SET @SQL = N'
             INSERT #TraceXML(ReportXML)
             SELECT col FROM OPENROWSET (
                           BULK ' + QUOTENAME(@Trace, '''') + N', SINGLE_BLOB
                    ) as xmldata(col)';
 
       EXEC (@SQL);
    
       CREATE PRIMARY XML INDEX PXML_TraceXML ON #TraceXML(ReportXML);
 
       WITH XMLNAMESPACES
       (
             'http://tempuri.org/TracePersistence.xsd' AS MY
       ),
       ShreddedWheat AS
       (
             SELECT
                    bpShredded.blocked_ecid,
                    bpShredded.blocked_spid,
                    bpShredded.blocked_inputbuffer,
                    bpShredded.blocked_waitime,
                    bpShredded.blocking_ecid,
                    bpShredded.blocking_spid,
                    bpShredded.blocking_inputbuffer,
                    bpShredded.monitorloop,
                    bpReports.bpReportXml,
                    bpReports.bpReportEndTime
             FROM #TraceXML
             CROSS APPLY
                    ReportXML.nodes('/MY:TraceData/MY:Events/MY:Event[@name="Blocked process report"]')
                    AS eventNodes(eventNode)
             CROSS APPLY
                    eventNode.nodes('./MY:Column[@name="EndTime"]')
                    AS endTimeNodes(endTimeNode)
             CROSS APPLY
                    eventNode.nodes('./MY:Column[@name="TextData"]')
                    AS bpNodes(bpNode)
             CROSS APPLY(
                    SELECT CAST(bpNode.value('(./text())[1]', 'nvarchar(max)') as xml),
                           CAST(LEFT(endTimeNode.value('(./text())[1]', 'varchar(max)'), 19) as datetime)
             ) AS bpReports(bpReportXml, bpReportEndTime)
             CROSS APPLY(
                    SELECT
                           monitorloop = bpReportXml.value('(//@monitorLoop)[1]', 'nvarchar(100)'),
                           blocked_spid = bpReportXml.value('(/blocked-process-report/blocked-process/process/@spid)[1]', 'int'),
                           blocked_ecid = bpReportXml.value('(/blocked-process-report/blocked-process/process/@ecid)[1]', 'int'),
                           blocked_inputbuffer = bpReportXml.value('(/blocked-process-report/blocked-process/process/inputbuf/text())[1]', 'nvarchar(max)'),
                           blocking_spid = bpReportXml.value('(/blocked-process-report/blocking-process/process/@spid)[1]', 'int'),
                           blocking_ecid = bpReportXml.value('(/blocked-process-report/blocking-process/process/@ecid)[1]', 'int'),
                           blocking_inputbuffer = bpReportXml.value('(/blocked-process-report/blocking-process/process/inputbuf/text())[1]', 'nvarchar(max)'),
                           blocked_waitime = bpReportXml.value('(/blocked-process-report/blocked-process/process/@waittime)[1]', 'bigint')
             ) AS bpShredded
       )
       INSERT #ReportsXML(blocked_ecid,blocked_spid,blocking_ecid,blocking_spid,
             monitorloop,bpReportXml,endTime)
       SELECT blocked_ecid,blocked_spid,blocking_ecid,blocking_spid,
             COALESCE(monitorloop, CONVERT(nvarchar(100), bpReportEndTime, 120), 'unknown'),
             bpReportXml,bpReportEndTime
       FROM ShreddedWheat;
    
       DROP TABLE #TraceXML
 
END
 
-- Organize and select blocked process reports
;WITH Blockheads AS
(
       SELECT blocking_spid, blocking_ecid, monitorloop, blocking_hierarchy_string
       FROM #ReportsXML
       EXCEPT
       SELECT blocked_spid, blocked_ecid, monitorloop, blocked_hierarchy_string
       FROM #ReportsXML
),
Hierarchy AS
(
       SELECT monitorloop, blocking_spid as spid, blocking_ecid as ecid,
             cast('/' + blocking_hierarchy_string as varchar(max)) as chain,
             0 as level
       FROM Blockheads
    
       UNION ALL
    
       SELECT irx.monitorloop, irx.blocked_spid, irx.blocked_ecid,
             cast(h.chain + irx.blocked_hierarchy_string as varchar(max)),
             h.level+1
       FROM #ReportsXML irx
       JOIN Hierarchy h
             ON irx.monitorloop = h.monitorloop
             AND irx.blocking_spid = h.spid
             AND irx.blocking_ecid = h.ecid
)
SELECT
       ISNULL(CONVERT(nvarchar(30), irx.endTime, 120),
             'Lead') as traceTime,
       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.blocked_waitime,
       bdp.last_trans_started as blocked_last_trans_started,
       bdp.wait_resource AS blocked_wait_resource,
       bgp.wait_resource AS blocking_wait_resource,
       bgp.[status] AS blocked_status,
       bdp.[status] AS blocking_status,
       bdp.lock_mode AS blocked_lock_mode,
       bdp.isolation_level as blocked_isolation_level,
       bgp.isolation_level as blocking_isolation_level,
       bdp.app AS blocked_app,
       DB_NAME(bdp.current_db) AS blocked_db,
       '-----> blocked statement' AS blocked_section,
       CAST('' + irx.blocked_bfinput + '' AS XML) AS blocked_input_buffer,
       CASE
             WHEN bdp.frame_blocked_process_xml IS NULL THEN CAST('' + irx.blocked_bfinput + '' AS XML)
             ELSE bdp.frame_blocked_process_xml
       END AS frame_blocked_process_xml,
       DB_NAME(bgp.current_db) AS blocking_db,
       bgp.app AS blocking_app,
       'blocking statement ----->' AS blocking_section,
       CAST('' + irx.blocking_bfinput + '' AS XML) AS blocking_input_buffer,
       CASE
             WHEN bgp.frame_blocking_process_xml IS NULL THEN CAST('' + irx.blocking_bfinput + '' AS XML)
             ELSE bgp.frame_blocking_process_xml
       END AS frame_blocking_process_xml,
       irx.bpReportXml
from Hierarchy h
left join #ReportsXML irx
       on irx.monitorloop = h.monitorloop
       and irx.blocked_spid = h.spid
       and irx.blocked_ecid = h.ecid
outer apply
(
       select
             T.x.value('(./process/@waitresource)[1]', 'nvarchar(256)') AS wait_resource,
             T.x.value('(./process/@lasttranstarted)[1]', 'datetime') as last_trans_started,
             T.x.value('(./process/@lockMode)[1]', 'nvarchar(60)') as lock_mode,
             T.x.value('(./process/@status)[1]', 'nvarchar(60)') as [status],
             T.x.value('(./process/@isolationlevel)[1]', 'nvarchar(60)') as isolation_level,
             T.x.value('(./process/@currentdb)[1]', 'int') as current_db,
             T.x.value('(./process/@clientapp)[1]', 'nvarchar(200)') as app,
             cast(
             (select SUBSTRING(txt.text,(ISNULL(T.x.value('./@stmtstart', 'int'), 0) / 2) + 1,
                           ((CASE ISNULL(T.x.value('./@stmtend', 'int'), -1)
                                  WHEN -1 THEN DATALENGTH(txt.text)
                                  ELSE T.x.value('./@stmtend', 'int')
                              END - ISNULL(T.x.value('./@stmtstart', 'int'), 0)) / 2) + 1) + CHAR(13) AS statement_txt
                       from bpReportXml.nodes('//blocked-process/process/executionStack/frame') AS T(x)
                       cross apply sys.dm_exec_sql_text(T.x.value('xs:hexBinary(substring((./@sqlhandle), 3))', 'varbinary(max)')) AS txt
                       for XML path('')) as xml) AS frame_blocked_process_xml
       from bpReportXml.nodes('//blocked-process') AS T(x)
) AS bdp
outer apply
(
       select
             T.x.value('(./process/@waitresource)[1]', 'nvarchar(256)') AS wait_resource,
             T.x.value('(./process/@status)[1]', 'nvarchar(60)') as [status],
             T.x.value('(./process/@isolationlevel)[1]', 'nvarchar(60)') as isolation_level,
             T.x.value('(./process/@currentdb)[1]', 'int') as current_db,
             T.x.value('(./process/@clientapp)[1]', 'nvarchar(200)') as app,
             cast(
             (select SUBSTRING(txt.text,(ISNULL(T.x.value('./@stmtstart', 'int'), 0) / 2) + 1,
                           ((CASE ISNULL(T.x.value('./@stmtend', 'int'), -1)
                                  WHEN -1 THEN DATALENGTH(txt.text)
                                  ELSE T.x.value('./@stmtend', 'int')
                              END - ISNULL(T.x.value('./@stmtstart', 'int'), 0)) / 2) + 1) + CHAR(13) AS statement_txt
                       from bpReportXml.nodes('//blocking-process/process/executionStack/frame') AS T(x)
                       cross apply sys.dm_exec_sql_text(T.x.value('xs:hexBinary(substring((./@sqlhandle), 3))', 'varbinary(max)')) AS txt
                       for XML path('')) as xml) AS frame_blocking_process_xml
             from bpReportXml.nodes('//blocking-process') AS T(x)
) AS bgp
order by h.monitorloop, h.chain
 
DROP TABLE #ReportsXML

Unfortunately I can’t show my customer context so I will show only a sample of my own test to explain how we can use this script. In fact, the generated result set is splitted into three main sections.

First section: Hierarchy blocked tree, lock resources and transaction isolation level

Let’s begin by the first category. You can see here the hierarchy tree and the blocked interactions that exist between the different processes. The above picture shows the process id = 72 that is blocking the process id = 73. In turn, the process = 73 is blocking other sessions (with id = 75, 77). Furthermore, the process 74 is at the same level than the process id = 73 and it is blocked by the process id = 72. Finally the process id = 76 is blocked by the process id = 74. A real can of worms isn’t it?

Displaying the blocking hierarchy tree is very useful in this case. In addition, I added the transaction isolation level used by all processes, the status of the processes, the locks and the resources related to the issue. As a reminder, these information are already in the blocked processes report and my task consisted in extracting these information in tabular format. We will use all of them later in this blog post. For the moment, let’s focus on the first hierarchy branch: 72 -> 73 -> 75 -> 77 and the resource that all concerned processes are hitting:

KEY: 6:72057594045595648 (089241b7b846) that we can split in three main parts

6 : Database id = 6 => AdventureWorks2012

72057594045595648 : The container hobt id of the partition that give us the schema, table and index as follows:

Person.Person.PK_Person_BusinessEntityID is a clustered index that includes the BusinessEntityID column.

(089241b7b846) :

The lock resource value that identifies the index key in the table Person.Person locked by the process id = 72. We may use the undocumented function %%lockres%% to locate the correct row in the table as follows:

At this point we know that the blocking process has started a transaction in repeatable read transaction isolation level and has not yet released the lock on the index key with value 14. This is why the session id = 73 is still pending because it attempts to access to the same resource by putting an S lock.

Let’s continue with the next sections of the result set:

Second section: blocking and blocked input buffers and their related frames

This second part provides detailed information of blocked statement information including the concerned application and the concerned databases as well.

Likewise, the last part provides the same kind of information but for the blocking statement(s):

We will correlate the information of the above sections. For example, if we take a look directly at the blocking input buffer of the process id = 72 we will discover the responsible that is the following stored procedure:

Next, the blocking frame identifies exactly the portion of code inside the stored procedure where the blocking issue has occurred:

WAITFOR DELAY ’00:02:00′;

Ok it seems that the stored procedure has started an explicit transaction with the repeatable read transaction isolation level and includes a WAITFOR DELAY command with a duration of 2 minutes. During this time, the different resources are still holding by the transaction because there is no transaction commit or transaction rollback and we are in repeatable read transaction isolation level. Let’s take a look at the stored procedure code:

We can confirm that we found in the first section, the repeatable read transaction isolation level used by the blocking session. In reality, it seems that we have two different resources holding by the above transaction. The first (index key = 14) and the second (index key = 14 + 100).

Now let’s switch to the blocked statement part. A quick look at the input buffer tells us that the session id = 73 is trying to access the same resource than the UPDATE part of the blocking process. It confirms what we saw in the first section: the process id = 73 is in suspended state because it is trying to put a S lock on the concerned resource that is not compatible with an X lock from the UPDATE statement of the process id = 72.

SELECT * FROM Person.Person WHERE BusinessEntityID = 114;

I will do not the same demonstration for all the lines in the result set but let’s finish by the process id = 74. Let’s go back to the first section. We can see that session id = 74 is trying to put an X lock on the following resource:

KEY: 6:72057594045726720 (58e9f9de4ab6)

Let’s apply the same rule that earlier and we may easily find the corresponding index key on the table Person.PersonPhone this time.

Now let’s continue to the next sections and let’s take a look at the blocking frame:

WAITFOR DELAY ’00:02:00′;

The same thing that the first case…. Finally let’s take a look at the blocking input buffer:

This time, it concerns an explicit transaction but with a different transaction isolation level: read committed mode. You can correlate with the first section by yourself. The blocking point concerns only the second part of the above query as indicated by the blocked_lock column in the first section: The process id = 74 is trying to put an X lock on a resource that is still holding by the process id = 72 (SELECT statement in repeatable read transaction isolation level).

The issue that I faced with my customer was pretty similar. In fact you have just to replace the WAITFOR DELAY command by a series of other pieces of code which deferred drastically the transaction commit time. In this case, having a precise idea of the blocking tree and the other information readable directly on a tabular format helped us to save a lot of time in order to resolve this issue.

Happy troubleshooting!

By David Barbarin