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

转自 http://sqlblog.com/blogs/jonathan_kehayias/archive/2010/12/21/an-xevent-a-day-21-of-31-the-future-tracking-blocking-in-denali.aspx

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

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.