Click here to monitor SSC
SQLServerCentral is supported by Red Gate Software Ltd.
 
Log in  ::  Register  ::  Not logged in
 
 
 

SQL Man of Mystery

Wes Brown is a PASS chapter leader and SQL Server MVP. He writes for SQL Server Central and maintains his blog at http://www.sqlserverio.com. Wes is Currently serving as a Senior Lead Consultant at Catapult Systems. Previous experiences include Product Manager for SQL Litespeed by Quest software and consultant to fortune 500 companies. He specializes in high availability, disaster recovery and very large database performance tuning. He is a frequent speaker at local user groups and SQLSaturdays.

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] (30) 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
  )
ON primary 

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.

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(30),
       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(30),
       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),
       [text]         [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],
               [text]
        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],
                       [text]
                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],
               [text]
        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],
                       [text]
                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],
                           [text])
              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.

UPDATE 5/30/2011

status was a varchar(20) should have been a varchar(30)

Comments

Posted by Jason Brimhall on 1 March 2011

Excellent work

Posted by Wesley Brown on 1 March 2011

Thanks! It loses it's formattting hopefully this is better.

Posted by Jason Brimhall on 2 March 2011

It looks better.

Posted by Frank Brouwer on 7 March 2011

Wow! Thanks, excellent job!!

In stead of excluding all I do not want, I need to observe 1 instance eg. 1 login or 1 programm. So I changed the code where it starts with

AND programname NOT IN( @ProcessesToIgnore )

- into -

AND programname IN( @ProcessesToIgnore )

- etc. -

should change variable names too I guess :-)

Posted by jennieoi23 84072 on 13 May 2011

Because of a truncation errors, we had to change

EventInfo      VARCHAR(255),  to

EventInfo      VARCHAR(4000),

The DBCC Inputbuffer eventinfo is defined nvarchar(4000)

Posted by Wesley Brown on 19 May 2011

Thanks, Fixed!

Posted by Tara Shankar Jana on 30 May 2011

This is an amazing script Wesley, way to go. I have modified it in my own ways for few other automation in the same script. Though this script works fine in SQL 2008, but is failing in SQL 2005 with truncation errors, i am using the same blocking scenario in SQL 2005 and SQL 2008 and its in the active_spids table insertion, as far as i can understand from the code. But i dont find a valid reason for this to not work in SQL 2005 and work fine with same data types in SQL 2008. Please suggest.

Msg 8152, Level 16, State 2, Procedure Alertonblocking, Line 130 String or binary data would be truncated.

The statement has been terminated.

Msg 8152, Level 16, State 2, Procedure Alertonblocking, Line 130 String or binary data would be truncated.

The statement has been terminated.

Posted by Wesley Brown on 30 May 2011

try it now status should have been a varchar(30)

Posted by crazy4sql on 19 October 2013

Sorry for commenting on quiet old thread. But I just found your query and tried to configure it in my environment.

I tied to customize it a bit by modifying two values

1) commenting out @duration

2) changing @max_wait_time to 2000ms

The surprise to me is, if I execute this with my change in sql 2008 it works but in 2005 it fails with error as "Msg 8152, Level 16, State 2, Line 134

String or binary data would be truncated."

Your reply will really help me.

Thanks in advance.

Posted by crazy4sql on 19 October 2013

just a quick update,

I able to find that it was breaking at "nt_domain" after changing the storage to varchar(200), it started working.

But,

stuck in another issue.

From sql 2k5 its only sending the details mail like in 2008. The mail I am getting in 2k5 is only this much

--------------------------------------------------------

The user below is at the head of the blocking chain on the listed server: __________________________________________________________________________ Server Name:********* TimeStamp: Oct 19 2013  1:41AM SPID: ****  Login Name: *********\*********                                                                                        NT Domain: *******

--------------------------------------------------------

Please help to fix it.

Posted by raj@db on 25 October 2013

Hi,

Need a small input here. Is that we need to create a job to execute the PROC to monitor the blockings?

Raj.

Leave a Comment

Please register or log in to leave a comment.