SQLDIY: Alert On Blocking Chains

Continuing the SQLDIY monitoring project we will take a look at tracking blocking events. I actually received a request to update this from a script I had made available at SQLServerCentral. This was a script from the grand old days of SQL Server 2000 and actually used xp_smtp_sendmail That Gert Drapers wrote about a million years ago in SQL Server time. With the advent of database mail it only made sense to update the procedure to use it. This still relies on sysprocesses but since it isn’t deprecated yet I’ve got at least three versions of SQL Server before I need to fix that. I did replace fn_get_sql with sys.dm_exec_sql_text since it is deprecated. Also, it simplified things by reducing the temporary table count by one thanks to the power of cross apply.

This module serves two purposes. One, to alert you based on criteria and thresholds. Two, track blocking issues over time. I found that concurrency issues crop up over time due to increase in data sizes. Tracking these blocking events may help you get in front of what may be a design flaw before it cripples your application.

As always, we create a new table BlockingChains in our local management database.

use Management
GO
drop table BlockingChains
go
CREATE TABLE [dbo].[BlockingChains] (
	[ServerName] [varchar] (255) NOT NULL,
	[SampleTime] [datetime] NOT NULL ,
	[Spid] [int] NULL ,
	[SpidBlocked] [int] NULL ,
	[WaitType] [varchar] (255) NULL ,
	[WaitTime] [bigint] NULL ,
	[PhysicalIO] [bigint] NULL ,
	[CPUInSeconds] [bigint] NULL ,
	[MemoryUsed] [bigint] NULL ,
	[Name] [nvarchar] (128)  NOT NULL ,
	[NumberOfOpenTransactions] [tinyint] NULL ,
	[Status] [varchar] (20)  NULL ,
	[HostName] [varchar] (50)  NULL ,
	[ProgramName] [varchar] (100)  NULL ,
	[CommandIssued] [varchar] (100)  NULL ,
	[DomainName] [varchar] (100)  NULL ,
	[DomainUserName] [varchar] (200)  NULL ,
	[LoginName] [varchar] (100)  NULL ,
	[EventTpe] [varchar] (255)  NULL ,
	[Parameters] [varchar] (255)  NULL ,
	[EventInfo] [varchar] (4000)  NULL ,
	[CommandText] [varchar] (max)  NULL
)
GO

Next comes the stored procedure. We have to get creative if we want to capture blocking chains under a minute. To do that we side step the sql agent a bit and have it start our job and let it run. The procedure then enters a loop and waits.

The procedure is pretty self explanatory and follows a pattern you will see me use again for gathering information at a resolution less than one minute. @Recivers should be a list of emails separated by a semicolon(;). the “ignore” variables are all comma separated lists. You may wish to ignore some things to keep the noise level down.

USE management

GO

CREATE PROCEDURE Alertonblocking @Duration          DATETIME = '08:00:00',
                                 -- Duration of data collection in hours.
                                 @IntervalSec       INT = 30,
                                 -- Approximate time in seconds the gathering interval.
                                 @MaxWaitTime       INT = 28000,
                                 -- This is in milliseconds.
                                 @Recivers          VARCHAR(8000) =
'test@email.com',-- Who all gets the emails.
                                 @ProcessesToIgnore VARCHAR(8000) = '',
                                 -- Ignore any processes that you don't want to trigger an alert.
                                 @HostsToIgnore     VARCHAR(8000) = '',
                                 -- Ignore any host that you don't want to trigger an alert.
                                 @LoginsToIgnore    VARCHAR(8000) = ''
-- Ignore any login that you don't want to trigger an alert.
AS
  SET nocount ON

  CREATE TABLE #active_spids
    (
       spid           INT,
       blocked        INT,
       waittype       VARCHAR(255),
       waittime       BIGINT,
       physical_io    BIGINT,
       cpu            BIGINT,
       memusage       BIGINT,
       [dbid]         INT,
       open_tran      TINYINT,
       [status]       VARCHAR(20),
       hostname       VARCHAR(50),
       [program_name] VARCHAR(100),
       cmd            VARCHAR(100),
       nt_domain      VARCHAR(100),
       nt_username    VARCHAR(200),
       loginame       VARCHAR(100),
       [sql_handle]   [BINARY] (20) NOT NULL,
       [stmt_start]   [INT] NOT NULL,
       [stmt_end]     [INT] NOT NULL,
       [sql_text]     [VARCHAR] (MAX)
    )

  CREATE TABLE #active_spids_info
    (
       spid           INT,
       blocked        INT,
       waittype       VARCHAR(255),
       waittime       BIGINT,
       physical_io    BIGINT,
       cpu            BIGINT,
       memusage       BIGINT,
       [dbid]         INT,
       open_tran      TINYINT,
       [status]       VARCHAR(20),
       hostname       VARCHAR(50),
       [program_name] VARCHAR(100),
       cmd            VARCHAR(100),
       nt_domain      VARCHAR(100),
       nt_username    VARCHAR(200),
       loginame       VARCHAR(100),
       [sql_handle]   [BINARY] (20) NOT NULL,
       [stmt_start]   [INT] NOT NULL,
       [stmt_end]     [INT] NOT NULL,
       eventtype      VARCHAR(255),
       parameters     VARCHAR(255),
       eventinfo      VARCHAR(4000),
                [VARCHAR] (MAX)
    )

  CREATE TABLE #event_info
    (
       spid         INT,
       eventtype    VARCHAR(255),
       [Parameters] VARCHAR(255),
       eventinfo    VARCHAR(4000)
    )

  DECLARE @TerminateGatheringDT DATETIME,-- when to stop gathering
          @WaitFor_Interval     DATETIME,
          @LastRecordingDT      DATETIME,
          @RecordingDT          DATETIME,
          @myError              INT,-- Local copy of @@ERROR
          @myRowCount           INT,-- Local copy of @@RowCount
          @msgText              NVARCHAR(4000),-- for error messages
          @dbname               VARCHAR(255),
          @svrname              VARCHAR(255),
          @datestart            AS DATETIME,
          @tstamp               VARCHAR(255),
          @spid1                VARCHAR(255),
          @dbname1              VARCHAR(255),
          @status               VARCHAR(255),
          @hostname             VARCHAR(255),
          @programname          VARCHAR(255),
          @cmd                  VARCHAR(255),
          @nt_domain            VARCHAR(255),
          @nt_username          VARCHAR(255),
          @loginame             VARCHAR(255),
          @text                 VARCHAR(8000),
          @msg                  VARCHAR(8000),
          @sub                  VARCHAR(8000),
          @timestamp            AS DATETIME,
          @spid                 INT,
          @sqlhandle            BINARY(20),
          @tsqlhandle           AS VARCHAR(255),
          @waittime             VARCHAR(255),
          @waittype             VARCHAR(255),
          @buffer               VARCHAR(255),
          @diffmsec             BIGINT

  --SET @Duration = '08:00:00' -- Duration of data collection
  --SET @IntervalSec = 30 -- Approx sec in the gathering interval
  --SET @MaxWaitTime = 28000 -- This is in miliseconds!!!
  --SET @Recivers = '' --who all gets the emails
  SET @diffmsec = Datediff(ms, CONVERT(DATETIME, '00:00:00', 8), @Duration)

  SELECT @WaitFor_Interval = Dateadd (s, @IntervalSec,
                             CONVERT (DATETIME, '00:00:00', 108
                                    )),
         @TerminateGatheringDT = Dateadd(ms, @diffmsec, Getdate())

  WHILE Getdate() <= @TerminateGatheringDT
    BEGIN
        TRUNCATE TABLE #active_spids

        TRUNCATE TABLE #active_spids_info

        TRUNCATE TABLE #event_info

        INSERT INTO #active_spids
        SELECT spid,
               blocked,
               waittype,
               waittime,
               physical_io,
               cpu,
               [memusage],
               a.dbid,
               open_tran,
               a.status,
               hostname,
               [program_name],
               cmd,
               nt_domain,
               nt_username,
               loginame,
               [sql_handle],
               [stmt_start],
               [stmt_end],
               
        FROM   (SELECT spid,
                       blocked,
                       'waittype' = CASE
                                      WHEN waittype = 0x0001 THEN
                                      'Exclusive table lock'
                                      WHEN waittype = 0x0003 THEN
                                      'Exclusive intent lock'
                                      WHEN waittype = 0x0004 THEN
                                      'Shared table lock'
                                      WHEN waittype = 0x0005 THEN
                                      'Exclusive page lock'
                                      WHEN waittype = 0x0006 THEN
                                      'Shared page lock'
                                      WHEN waittype = 0x0007 THEN
                                      'Update page lock'
                                      WHEN waittype = 0x0013 THEN
                                      'Buffer resource lock (exclusive) request'
                                      WHEN waittype = 0x0013 THEN
                       'Miscellaneous I/O (sort, audit, direct xact log I/O)'
                       WHEN waittype = 0x0020 THEN 'Buffer in I/O'
                       WHEN waittype = 0x0022 THEN 'Buffer being dirtied'
                       WHEN waittype = 0x0023 THEN 'Buffer being dumped'
                       WHEN waittype = 0x0081 THEN 'Write the TLog'
                       WHEN waittype = 0x0200 THEN 'Parallel query coordination'
                       WHEN waittype = 0x0208 THEN 'Parallel query coordination'
                       WHEN waittype = 0x0420 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0421 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0422 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0423 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0424 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0425 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0800 THEN 'Network I/O completion'
                       WHEN waittype = 0x8001 THEN 'Exclusive table lock'
                       WHEN waittype = 0x8003 THEN 'Exclusive intent lock'
                       WHEN waittype = 0x8004 THEN 'Shared table lock'
                       WHEN waittype = 0x8005 THEN 'Exclusive page lock'
                       WHEN waittype = 0x8006 THEN 'Shared page lock'
                       WHEN waittype = 0x8007 THEN 'Update page lock'
                       WHEN waittype = 0x8011 THEN
                       'Buffer resource lock (shared) request'
                       ELSE 'OLEDB/Miscellaneous'
                                    END,
                       waittime,
                       physical_io,
                       cpu,
                       [memusage],
                       sp.dbid,
                       open_tran,
                       status,
                       hostname,
                       [program_name],
                       cmd,
                       nt_domain,
                       nt_username,
                       loginame,
                       [sql_handle],
                       [stmt_start],
                       [stmt_end],
                       
                FROM   MASTER.dbo.sysprocesses sp WITH(nolock)
                       CROSS APPLY sys.Dm_exec_sql_text([sql_handle]))a
        WHERE  blocked > 0
               AND waittime > @MaxWaitTime
        UNION ALL
        SELECT spid,
               blocked,
               waittype,
               waittime,
               physical_io,
               cpu,
               [memusage],
               a.dbid,
               open_tran,
               a.status,
               hostname,
               [program_name],
               cmd,
               nt_domain,
               nt_username,
               loginame,
               [sql_handle],
               [stmt_start],
               [stmt_end],
               
        FROM   (SELECT spid,
                       blocked,
                       'waittype' = CASE
                                      WHEN waittype = 0x0001 THEN
                                      'Exclusive table lock'
                                      WHEN waittype = 0x0003 THEN
                                      'Exclusive intent lock'
                                      WHEN waittype = 0x0004 THEN
                                      'Shared table lock'
                                      WHEN waittype = 0x0005 THEN
                                      'Exclusive page lock'
                                      WHEN waittype = 0x0006 THEN
                                      'Shared page lock'
                                      WHEN waittype = 0x0007 THEN
                                      'Update page lock'
                                      WHEN waittype = 0x0013 THEN
                                      'Buffer resource lock (exclusive) request'
                                      WHEN waittype = 0x0013 THEN
                       'Miscellaneous I/O (sort, audit, direct xact log I/O)'
                       WHEN waittype = 0x0020 THEN 'Buffer in I/O'
                       WHEN waittype = 0x0022 THEN 'Buffer being dirtied'
                       WHEN waittype = 0x0023 THEN 'Buffer being dumped'
                       WHEN waittype = 0x0081 THEN 'Write the TLog'
                       WHEN waittype = 0x0200 THEN 'Parallel query coordination'
                       WHEN waittype = 0x0208 THEN 'Parallel query coordination'
                       WHEN waittype = 0x0420 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0421 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0422 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0423 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0424 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0425 THEN 'Buffer I/O latch'
                       WHEN waittype = 0x0800 THEN 'Network I/O completion'
                       WHEN waittype = 0x8001 THEN 'Exclusive table lock'
                       WHEN waittype = 0x8003 THEN 'Exclusive intent lock'
                       WHEN waittype = 0x8004 THEN 'Shared table lock'
                       WHEN waittype = 0x8005 THEN 'Exclusive page lock'
                       WHEN waittype = 0x8006 THEN 'Shared page lock'
                       WHEN waittype = 0x8007 THEN 'Update page lock'
                       WHEN waittype = 0x8011 THEN
                       'Buffer resource lock (shared) request'
                       ELSE 'OLEDB/Miscellaneous'
                                    END,
                       waittime,
                       physical_io,
                       cpu,
                       [memusage],
                       sp.dbid,
                       open_tran,
                       status,
                       hostname,
                       [program_name],
                       cmd,
                       nt_domain,
                       nt_username,
                       loginame,
                       [sql_handle],
                       [stmt_start],
                       [stmt_end],
                       
                FROM   MASTER.dbo.sysprocesses sp WITH(nolock)
                       CROSS APPLY sys.Dm_exec_sql_text([sql_handle])
                WHERE  spid IN (SELECT blocked
                                FROM   MASTER.dbo.sysprocesses WITH(nolock)
                                WHERE  blocked > 0
                                       AND waittime > @MaxWaitTime)) a
        ORDER  BY blocked

        --loop through the spids without a cursor
        WHILE (SELECT COUNT(spid)
               FROM   #active_spids) > 0
          BEGIN
              SET @spid = (SELECT TOP 1 spid
                           FROM   #active_spids
                           ORDER  BY spid)

              --grab the top spid
              INSERT INTO #active_spids_info
                          (spid,
                           blocked,
                           waittype,
                           waittime,
                           physical_io,
                           cpu,
                           [memusage],
                           dbid,
                           open_tran,
                           status,
                           hostname,
                           [program_name],
                           cmd,
                           nt_domain,
                           nt_username,
                           loginame,
                           [sql_handle],
                           [stmt_start],
                           [stmt_end],
                           )
              SELECT TOP 1 spid,
                           blocked,
                           waittype,
                           waittime,
                           physical_io,
                           cpu,
                           [memusage],
                           dbid,
                           open_tran,
                           status,
                           hostname,
                           [program_name],
                           cmd,
                           nt_domain,
                           nt_username,
                           loginame,
                           [sql_handle],
                           [stmt_start],
                           [stmt_end],
                           [sql_text]
              FROM   #active_spids
              ORDER  BY spid

              INSERT INTO #event_info
                          (eventtype,
                           parameters,
                           eventinfo)
              EXEC('DBCC INPUTBUFFER (' + @spid + ') WITH NO_INFOMSGS')

              --get the inputbuffer
              EXEC('update #event_info set spid = '+@spid+' where spid IS NULL')

              --add the spid to the input buffer data
              SELECT @sqlhandle = sql_handle
              FROM   #active_spids
              WHERE  spid = @spid

              DELETE FROM #active_spids
              WHERE  spid = @spid
          --remove the spid processed
          END

        UPDATE #active_spids_info
        SET    #active_spids_info.eventtype = #event_info.eventtype,
               #active_spids_info.parameters = #event_info.parameters,
               #active_spids_info.eventinfo = #event_info.eventinfo
        FROM   #active_spids_info,
               #event_info
        WHERE  #active_spids_info.spid = #event_info.spid

        --join all the info into one table
        SET @timestamp = Getdate()

        --select statement to return results
        INSERT INTO management.dbo.blockingchains
        SELECT @@SERVERNAME,
               @timestamp       AS tstamp,
               a.spid,
               a.blocked,
               a.waittype,
               a.waittime,
               a.physical_io,
               ( a.cpu / 1000 ) AS cpu_in_seconds,
               a.[memusage],
               b.[name],
               a.open_tran,
               a.status,
               a.hostname,
               a.[program_name],
               a.cmd,
               a.nt_domain,
               a.nt_username,
               a.loginame,
               a.eventtype,
               a.parameters,
               a.eventinfo,
               a.TEXT
        FROM   #active_spids_info a
               INNER JOIN MASTER.dbo.sysdatabases b
                 ON a.dbid = b.dbid

        IF ( (SELECT MAX(sampletime)
              FROM   management.dbo.blockingchains
              WHERE  spidblocked = 0
                     AND programname NOT IN( @ProcessesToIgnore )
                     AND hostname NOT IN( @HostsToIgnore )
                     AND ( domainname NOT IN( @LoginsToIgnore )
                            OR loginname NOT IN( @LoginsToIgnore ) )) =
             @timestamp
           )
          BEGIN
              SELECT @sub = 'Blocking Issues - ' + @@SERVERNAME

              SELECT @tstamp = sampletime,
                     @spid1 = spid,
                     @status = status,
                     @hostname = Isnull(hostname, ''),
                     @programname = Isnull([programname], ''),
                     @cmd = Isnull(commandissued, ''),
                     @nt_domain = Isnull(domainname, ''),
                     @nt_username = Isnull(domainusername, ''),
                     @loginame = Isnull(loginname, ''),
                     @text = Isnull(commandtext, ''),
                     @waittime = (SELECT MAX(waittime)
                                  FROM   management.dbo.blockingchains
                                  WHERE  sampletime = (SELECT MAX(sampletime)
                                                       FROM
                                         management.dbo.blockingchains)),
                     @waittype = Isnull(waittype, ''),
                     @buffer = Isnull(eventinfo, '')
              FROM   management.dbo.blockingchains
              WHERE  sampletime = (SELECT MAX(sampletime)
                                   FROM   management.dbo.blockingchains)
                     AND spidblocked = 0

              SELECT @msg =
  'The user below is at the head of the blocking chain on the listed server:'
  +
         CHAR(13) +
  '__________________________________________________________________________'
  +
                CHAR(13) + 'Server Name:' + @@SERVERNAME + CHAR(13) +
                'TimeStamp: ' + @tstamp + CHAR(13) + 'SPID: ' + @spid1 + CHAR(13)
  + 'Login Name: ' + @loginame + CHAR(13) + 'NT Domain: ' + @nt_domain + CHAR(13)
  + 'NT Username: ' + @nt_username + CHAR(13) + 'Host Name: ' + @hostname +  CHAR(13) 
  + 'Command: ' + @cmd + CHAR(13) + 'Program Name: ' +
                @programname + CHAR(13) + 'Wait Type: ' + @waittype + CHAR(13)
  +
                'Maximum Wait Time For Blocked Thread: ' + @waittime + CHAR(13) +
                'Input Buffer: ' + @buffer + CHAR(13) + 'Status: ' + @status +
                CHAR(13) + 'SQL String:' + CHAR(13) +
                '--WARNING CAN BE LONG AND MAY NOT BE THE WHOLE TEXT!!!--' +
  CHAR(13) + @text

  EXEC msdb.dbo.Sp_send_dbmail
    @recipients = @Recivers,
    @body = @msg,
    @subject = @sub;
  END

  WAITFOR delay @WaitFor_Interval -- delay
  END

  DROP TABLE #active_spids

  DROP TABLE #active_spids_info

  DROP TABLE #event_info

If you find a bug or have an issue just add a comment here and I’ll address it.

Updated:
Fixed bug where EventInfo was too small move from 255 to 4000