An XEvent a Day (21 of 31) – The Future – Tracking Blocking in Denali

One of my favorite features that was added to SQL Server 2005 has been the Blocked Process Report trace event which collects an XML report whenever a process is blocked inside of the database engine longer than the user configurable threshold.  I wrote an article about this feature on SQL Server Central  two years ago titled Using the Blocked Process Report in SQL Server 2005/2008.  One of the aspects of this feature is that it requires that you either have a SQL Trace running that captures the event, or you configure Event Notifications on the server to capture the event information in a Service Broker Queue, neither of which is overly difficult to accomplish.  In SQL Server Denali CTP1, there is a new Extended Event, sqlserver.blocked_process_report, that makes this even easier to use.  We can now create an Event Session that exists in our SQL Server and is waiting to be started to capture blocked process information as needed.  However, we still have to set the ‘blocked process threshold’ sp_configure option to set the threshold at which blocked process report information is generated by Database Engine, firing the Event in our Event Session.

CREATE EVENT SESSION MonitorBlocking
ON SERVER
ADD EVENT sqlserver.blocked_process_report
ADD TARGET package0.ring_buffer(SET MAX_MEMORY=2048)
WITH (MAX_DISPATCH_LATENCY = 5SECONDS)
GO
ALTER EVENT SESSION MonitorBlocking
ON SERVER
STATE=START
GO
EXECUTE sp_configure 'show advanced options', 1
GO
RECONFIGURE
GO
EXECUTE sp_configure 'blocked process threshold', 15
GO
RECONFIGURE
GO
EXECUTE sp_configure 'show advanced options', 0
GO
RECONFIGURE
GO

To test this Event Session, we can open two New Query Windows in SSMS and connect them to our database engine.  Then in one window run the following code:

USE [tempdb]
GO
CREATE TABLE t1 (RowID int identity primary key)
GO
BEGIN TRANSACTION
INSERT INTO t1 DEFAULT VALUES
WAITFOR DELAY '00:00:30'
COMMIT

Then in the other window run the following code:

USE [tempdb]
GO
SELECT * FROM t1

The first query will block the execution of the second query until it completes, generating our blocked process report in the ring_buffer Target for our Event Session.  To get the information from the ring_buffer target, we can run a quick XQuery to parse the Target (at this point in the series, you should be an XQuery pro):

-- Query the XML to get the Target Data
SELECT 
    n.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    n.value('(event/@package)[1]', 'varchar(50)') AS package_name,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            n.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    ISNULL(n.value('(event/data[@name="database_id"]/value)[1]', 'int'),
            n.value('(event/action[@name="database_id"]/value)[1]', 'int')) as [database_id],
    n.value('(event/data[@name="database_name"]/value)[1]', 'nvarchar(128)') as [database_name],
    n.value('(event/data[@name="object_id"]/value)[1]', 'int') as [object_id],
    n.value('(event/data[@name="index_id"]/value)[1]', 'int') as [index_id],
    CAST(n.value('(event/data[@name="duration"]/value)[1]', 'bigint')/1000000.0 AS decimal(6,2)) as [duration_seconds],
    n.value('(event/data[@name="lock_mode"]/text)[1]', 'nvarchar(10)') as [file_handle],
    n.value('(event/data[@name="transaction_id"]/value)[1]', 'bigint') as [transaction_id],
    n.value('(event/data[@name="resource_owner_type"]/text)[1]', 'nvarchar(10)') as [resource_owner_type],
    CAST(n.value('(event/data[@name="blocked_process"]/value)[1]', 'nvarchar(max)') as XML) as [blocked_process_report]
FROM
(    SELECT td.query('.') as n
    FROM 
    (
        SELECT CAST(target_data AS XML) as target_data
        FROM sys.dm_xe_sessions AS s    
        JOIN sys.dm_xe_session_targets AS t
            ON s.address = t.event_session_address
        WHERE s.name = 'MonitorBlocking'
          AND t.target_name = 'ring_buffer'
    ) AS sub
    CROSS APPLY target_data.nodes('RingBufferTarget/event') AS q(td)
) as tab
GO

image

The output of the Event in Extended Events contains some additional information to the blocked process report in XML format including the database_id, object_id, index_id, duration, lock_mode, transaction_id, and resource_owner_type for the blocking resource.  Clicking on the blocked process report XML will open it up in Management Studio as an XML document allowing detailed analysis of the blocking to be performed.

<blocked-process-report>
  <blocked-process>
    <process id="process2eb8bda8" taskpriority="0" logused="0" waitresource="KEY: 2:2666130980878942208 (61a06abd401c)" 
             waittime="25480" ownerId="12748" transactionname="SELECT" lasttranstarted="2010-12-21T18:19:03.263" 
             XDES="0x2dfb9c10" lockMode="S" schedulerid="1" kpid="2484" status="suspended" spid="60" sbid="0" ecid="0" 
             priority="0" trancount="0" lastbatchstarted="2010-12-21T18:19:03.263" 
             lastbatchcompleted="2010-12-21T18:19:03.263" clientapp="Microsoft SQL Server Management Studio - Query" 
             hostname="WIN-5B9V8JPLP3H" hostpid="2708" loginname="WIN-5B9V8JPLP3H\Administrator" 
             isolationlevel="read committed (2)" xactid="12748" currentdb="2" lockTimeout="4294967295" 
             clientoption1="671090784" clientoption2="390200">
      <executionStack>
        <frame line="1" sqlhandle="0x02000000d9de7b2f4f3a78e40f100bc02a84efbb9f01a84d" />
      </executionStack>
      <inputbuf>
SELECT * FROM t1   </inputbuf>
    </process>
  </blocked-process>
  <blocking-process>
    <process status="suspended" waittime="27430" spid="57" sbid="0" ecid="0" priority="0" trancount="1" 
             lastbatchstarted="2010-12-21T18:19:01.437" lastbatchcompleted="2010-12-21T18:13:25.637" 
             clientapp="Microsoft SQL Server Management Studio - Query" hostname="WIN-5B9V8JPLP3H" 
             hostpid="2708" loginname="WIN-5B9V8JPLP3H\Administrator" isolationlevel="read committed (2)" 
             xactid="12733" currentdb="2" lockTimeout="4294967295" clientoption1="671090784" clientoption2="390200">
      <executionStack>
        <frame line="3" stmtstart="100" stmtend="150" sqlhandle="0x020000005a74b3030117e049389a93b2ce5bfb48e272f938" />
      </executionStack>
      <inputbuf>
BEGIN TRANSACTION
INSERT INTO t1 DEFAULT VALUES
WAITFOR DELAY '00:00:30'
COMMIT   </inputbuf>
    </process>
  </blocking-process>
</blocked-process-report>

The output of the blocked process report in Extended Events is the same as the blocked process report from SQL Trace and Event Notifications.  This is only a new mechanism of collecting this information, and when Denali releases RTM, this will be an Event Session that I install on my Denali based servers as a part of my configuration scripts, having it ready to activate when necessary.

Make sure that you turn off the generation of blocked process reports by changing the ‘blocked process threshold’ sp_configure option back to 0 (zero) whenever you are not actively looking for blocked processes.

5 thoughts on “An XEvent a Day (21 of 31) – The Future – Tracking Blocking in Denali

  1. When I run this query to get the results on SQL 2012, the final column, [blocked_process_report] only contains the text of the queries, not the full xml of the blocked_process node. Any idea why?

  2. Hey Eric,

    The XML changed in SQL Server 2012 CTP3 so that now it is actually XML and not the value as text. You need to .query() the report now like this:

    SELECT
    event_data.query(‘event/data[@name=”blocked_process”]/value/blocked-process-report’) as blocked_process_report
    FROM
    ( SELECT XEvent.query(‘.’) AS event_data
    FROM
    ( — Cast the target_data to XML
    SELECT CAST(target_data AS XML) AS TargetData
    FROM sys.dm_xe_session_targets st
    JOIN sys.dm_xe_sessions s
    ON s.address = st.event_session_address
    WHERE name = ‘blocking’
    AND target_name = ‘ring_buffer’
    ) AS Data
    — Split out the Event Nodes
    CROSS APPLY TargetData.nodes (‘RingBufferTarget/event[@name=”blocked_process_report”]’) AS XEventData (XEvent)
    ) AS tab (event_data)

    1. Thank you again. I like those extra columns, so I just replaced the line with this:

      n.query('(event/data[@name="blocked_process"]/value/blocked-process-report)[1]') as [blocked_process_report]

  3. Thank you so much. Does this event exist in SQL 2008 R2? I am getting below error.

    The event name, “sqlserver.blocked_process_report”, is invalid, or the object could not be found

Leave a Reply

Your email address will not be published. Required fields are marked *

Other articles

Imagine feeling confident enough to handle whatever your database throws at you.

With training and consulting from SQLskills, you’ll be able to solve big problems, elevate your team’s capacity, and take control of your data career.