Blog

A lot of folks would have you think that Extended Events need to be complicated and involve copious amounts of XML shredding and throwing things across the office. I’m here to tell you that it doesn’t have to be so bad.

Collecting Blocked Process Reports and Deadlocks Using Extended Events

When you want to find blocking, you probably turn to the blocked process report. You mess around with profiler on your SQL Server 2012 box. You probably feel a little bit dirty for clunking around in that old interface, but it gets the job done.

There’s a better way… Well, there is at least a less awful way: Extended Events.

CREATE EVENT SESSION [blocked_process] ON SERVER
ADD EVENT sqlserver.blocked_process_report(
    ACTION(sqlserver.client_app_name,
           sqlserver.client_hostname,
           sqlserver.database_name)) ,
ADD EVENT sqlserver.xml_deadlock_report (
    ACTION(sqlserver.client_app_name,
           sqlserver.client_hostname,
           sqlserver.database_name))
ADD TARGET package0.asynchronous_file_target
(SET filename = N'c:\temp\XEventSessions\blocked_process.xel',
     metadatafile = N'c:\temp\XEventSessions\blocked_process.xem',
     max_file_size=(65536),
     max_rollover_files=5)
WITH (MAX_DISPATCH_LATENCY = 5SECONDS)
GO

/* Make sure this path exists before you start the trace! */

With that, you’ve created an Extended Events session to grab blocked processes and deadlocks. Why both? The blocked process report makes use of the deadlock detector. Since large amounts of blocking are frequently synonymous with deadlocking, it makes sense to grab both at the same time. There are a few other things we’ll need to do to make sure you can collect blocked processes:

EXEC sp_configure ‘show advanced options’, 1 ;
GO
RECONFIGURE ;
GO
/* Enabled the blocked process report */
EXEC sp_configure 'blocked process threshold', '5';
RECONFIGURE
GO
/* Start the Extended Events session */
ALTER EVENT SESSION [blocked_process] ON SERVER
STATE = START;

At this point, you’ll be collecting the blocked process report with Extended Events. There’s no profiler session to set up, just start and stop the Extended Event session at your leisure.

Reading the Block Process Report from Extended Events

We’re saving the blocked process report to disk using Extended Events. Now what?

We need to get that blocked process data out of the Extended Events files and somewhere that we can better analyze it.

WITH events_cte AS (
  SELECT
    xevents.event_data,
    DATEADD(mi,
    DATEDIFF(mi, GETUTCDATE(), CURRENT_TIMESTAMP),
    xevents.event_data.value(
      '(event/@timestamp)[1]', 'datetime2')) AS [event time] ,
    xevents.event_data.value(
      '(event/action[@name="client_app_name"]/value)[1]', 'nvarchar(128)')
      AS [client app name],
    xevents.event_data.value(
      '(event/action[@name="client_hostname"]/value)[1]', 'nvarchar(max)')
      AS [client host name],
    xevents.event_data.value(
      '(event[@name="blocked_process_report"]/data[@name="database_name"]/value)[1]', 'nvarchar(max)')
      AS [database name],
    xevents.event_data.value(
      '(event[@name="blocked_process_report"]/data[@name="database_id"]/value)[1]', 'int')
      AS [database_id],
    xevents.event_data.value(
      '(event[@name="blocked_process_report"]/data[@name="object_id"]/value)[1]', 'int')
      AS [object_id],
    xevents.event_data.value(
      '(event[@name="blocked_process_report"]/data[@name="index_id"]/value)[1]', 'int')
      AS [index_id],
    xevents.event_data.value(
      '(event[@name="blocked_process_report"]/data[@name="duration"]/value)[1]', 'bigint') / 1000
      AS [duration (ms)],
    xevents.event_data.value(
      '(event[@name="blocked_process_report"]/data[@name="lock_mode"]/text)[1]', 'varchar')
      AS [lock_mode],
    xevents.event_data.value(
      '(event[@name="blocked_process_report"]/data[@name="login_sid"]/value)[1]', 'int')
      AS [login_sid],
    xevents.event_data.query(
      '(event[@name="blocked_process_report"]/data[@name="blocked_process"]/value/blocked-process-report)[1]')
      AS blocked_process_report,
    xevents.event_data.query(
      '(event/data[@name="xml_report"]/value/deadlock)[1]')
      AS deadlock_graph
  FROM    sys.fn_xe_file_target_read_file
    ('C:\temp\XEventSessions\blocked_process*.xel',
     'C:\temp\XEventSessions\blocked_process*.xem',
     null, null)
    CROSS APPLY (SELECT CAST(event_data AS XML) AS event_data) as xevents
)
SELECT
  CASE WHEN blocked_process_report.value('(blocked-process-report[@monitorLoop])[1]', 'nvarchar(max)') IS NULL
       THEN 'Deadlock'
       ELSE 'Blocked Process'
       END AS ReportType,
  [event time],
  CASE [client app name] WHEN '' THEN ' -- N/A -- '
                         ELSE [client app name]
                         END AS [client app _name],
  CASE [client host name] WHEN '' THEN ' -- N/A -- '
                          ELSE [client host name]
                          END AS [client host name],
  [database name],
  COALESCE(OBJECT_SCHEMA_NAME(object_id, database_id), ' -- N/A -- ') AS [schema],
  COALESCE(OBJECT_NAME(object_id, database_id), ' -- N/A -- ') AS [table],
  index_id,
  [duration (ms)],
  lock_mode,
  COALESCE(SUSER_NAME(login_sid), ' -- N/A -- ') AS username,
  CASE WHEN blocked_process_report.value('(blocked-process-report[@monitorLoop])[1]', 'nvarchar(max)') IS NULL
       THEN deadlock_graph
       ELSE blocked_process_report
       END AS Report
FROM events_cte
ORDER BY [event time] DESC ;

In this query, you read from an Extended Events session that’s being saved to disk and perform XML shredding to get client information. It isn’t a pretty query, but it does the job very well.

Viewing the Extended Events Deadlock Graphs

Extended Events deadlock graphs use a slightly different XML schema than what SSMS expects. You should see an error along the lines of “There is an error in XML document”. For folks using SQL Server 2012 and earlier, you can either parse the XML by hand or use SQL Sentry Plan Explorer.

Viewing the Extended Events Blocked Process Report

But what about the blocked process report? After all, your users are complaining about blocking, right?

Michael J. Swart has created tools to view the blocked process report. It’d be awesome if you could use it, but Michael’s blocked process report viewer uses the output of a server side trace to read blocking information. These Extended Events files are different enough that you can’t use them outright. You can, however, create a table that will let you use the blocked process report viewer:

CREATE TABLE bpr (
    EndTime DATETIME,
    TextData XML,
    EventClass INT DEFAULT(137)
);
GO

WITH events_cte AS (
    SELECT
        DATEADD(mi,
        DATEDIFF(mi, GETUTCDATE(), CURRENT_TIMESTAMP),
        xevents.event_data.value('(event/@timestamp)[1]',
           'datetime2')) AS [event_time] ,
        xevents.event_data.query('(event[@name="blocked_process_report"]/data[@name="blocked_process"]/value/blocked-process-report)[1]')
            AS blocked_process_report
    FROM    sys.fn_xe_file_target_read_file
        ('C:\temp\XEventSessions\blocked_process*.xel',
         'C:\temp\XEventSessions\blocked_process*.xem',
         null, null)
        CROSS APPLY (SELECT CAST(event_data AS XML) AS event_data) as xevents
)
INSERT INTO bpr (EndTime, TextData)
SELECT
    [event_time],
    blocked_process_report
FROM events_cte
WHERE blocked_process_report.value('(blocked-process-report[@monitorLoop])[1]', 'nvarchar(max)') IS NOT NULL
ORDER BY [event_time] DESC ;

EXEC sp_blocked_process_report_viewer @Trace='bpr', @Type='TABLE';

While you still have to read the XML yourself, this will give you a view into how deep the blocking hierarchies can go. Collecting this data with Extended Events mean that you won’t have to sit at your desk, running queries, and waiting for blocking occur.

Extended Events – Not That Hard

Extended Events aren’t difficult to use. They provide a wealth of information about SQL Server and make it easier to collect information from complex or difficult to diagnose scenarios. You really can collect as much or as little information as you want from SQL Server. When you get started, the vast majority of your work will be spent either looking up Extended Events to use or formatting the output of the queries into something meaningful.

↑ Back to top
  1. Thanks for plugging the blocked process report viewer.
    I haven’t revisited the tool in a while. Extended events for blocked processes didn’t exist when I wrote the blocked process report viewer. Maybe it’s time to revisit it. If I do, I’ll let you know.

  2. Minor typo, you have:

    EXEC sp_configure ‘blocked process report’, ’5′;
    RECONFIGURE
    GO

    But it should be:

    EXEC sp_configure ‘blocked_process’, ’5′;
    RECONFIGURE
    GO

    Regards,
    EWG

  3. Hello Jeremiah,

    Really useful post. I am testing it right now and will use it in a customer, who’s complaining about performance problems.

    Just a couple of minor things:

    SQL throws an error when starting the event session if the path selected for the event files does not exist. The “problem” is that you don’t see any error when creating the event session, but as I said, when starting it:

    Msg 25602, Level 17, State 22, Line 1
    The target, “5B2DA06D-898A-43C8-9309-39BBBE93EBBD.package0.event_file”, encountered a configuration error during initialization. Object cannot be added to the event session. The operating system returned error 3: ‘The system cannot find the path specified.
    ‘ while creating the file ‘c:\myFoñder\XEventSessions\blocked_process_0_130391967440060000.xel’.

    The second question is that I think that you should add this

    sp_configure ‘show advanced options’, 1 ;
    GO
    RECONFIGURE ;
    GO

    just before

    EXEC sp_configure ‘blocked process threshold’, ’5′;
    RECONFIGURE
    GO

    BTW, it works for me with this literal instead of ‘blocked_process’, in spite of what Elijah pointed out.

    Kind regards,

    Jaime

    • Thanks for pointing that out! I’ve added the code to show advanced options into the example. I have to admit – it’s pretty rare to encounter a SQL Server that isn’t using that setting any more. I’ll also admit to never having seen SQL Server use an underscore in an sp_configure setting. Something tells me that’s from the dark ages of SQL Server, or else it exists to give warm fuzzies to the Oracle crowd.

  4. Pingback: (SFTW) SQL Server Links 14/03/14 • John Sansom

  5. Hi

    Thanks for the post. Just want to make sure, is this valid for SQL SERVER 2008R2 SP2 as well.

    Thanks
    Murali

    • Murali – when in doubt, try it out. ;-) It’ll take less time to give it a shot on your system than it would to post this comment, believe it or not. Enjoy the journey!

    • Hi Murali,

      I can tell you that the event sqlserver.blocked_process_report does not exist in SQL Server 2008 (R2).
      You can check for available events with this script:

      select p.name as package, xo.name as object_name, xo.description, xo.object_type
      from sys.dm_xe_objects xo
      join sys.dm_xe_packages p
      on xo.package_guid = p.guid

      Also the event action name sqlserver.database_name produces the following error:
      Msg 25623, Level 16, State 3, Line 1
      The event action name, “sqlserver.database_name”, is invalid, or the object could not be found

      Regards,

      Jaime

  6. Great article, thanks. It’s got me started on using extended events to track down some issues that one of our clients is having with performance on their system.

    Can you recommend any resources for further reading?

    I am trying to work out how, using the sqlserver.lock_released event, I can find the table which a page or extent level lock relates. I’d have thought it would have been straightforward, and something that others would have done before, but can’t find information.

    thanks

    • Hi David,

      I haven’t checked into this myself, but there’s some great information in Lock:Released documentation as well as a few tutorials over on John Huag’s blog here and here.

      Basically, object_id is your… object_id, res0 is page and res1 is the file number.

      I’d be careful setting up extended events sessions capturing locks. You could also use sp_BlitzIndex and look at the aggressive indexes or even query sys.dm_db_index_operational_stats and get two samples to help you figure out which index is having heavy locking.

      Hope that helps!

      • Hi Jeremiah,

        Thanks for the advice. sys.dm_db_index_operational_stats gives me a lot of what I need.

        I also think that I can use the TransactionID field to match page level locks with the Intent, IS, mode lock taken on the table. That gives me a clearer picture of what’s happening.

        Cheers

        David

  7. Pingback: Recording Deadlocks via Extended Events and XML | :: NickBurns

Leave a Reply

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

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>

css.php