Logging blocks - SQL Server Forums

Please start any new threads on our new site at https://forums.sqlteam.com. We've got lots of great SQL Server experts to answer whatever question you can come up with.

All Forums

SQL Server 2005 Forums

SQL Server Administration (2005)

Logging blocks

Author

Topic

coolerbob
Aged Yak Warrior

841 Posts

Posted - 2008-04-23 : 11:29:32

I would like to log blocks to see what causes it.

One hack of a way to do it is to run code similar to that which populates the blk column in sp_who; on a job every 5 seconds. It would store the results of code similar to the sp_who output whenever any of the rows has a value greater than zero in the blk column.

This way, I can see what was going on at the time there was a problem.
Does anyone have a better strategy for this?

sodeep
Master Smack Fu Yak Hacker

7174 Posts

Posted - 2008-04-23 : 13:12:32

1)query sysprocesses system table
2) Use DBCC inputbuffer(spid) to find what statements caused it
3) mail it to DBA using DBmail by creating jobs

rmiao
Master Smack Fu Yak Hacker

7266 Posts

Posted - 2008-04-23 : 22:59:26

Does sysprocesses have command column?

sodeep
Master Smack Fu Yak Hacker

7174 Posts

Posted - 2008-04-24 : 10:08:21

They do have.

coolerbob
Aged Yak Warrior

841 Posts

Posted - 2008-04-24 : 10:48:22

3 cheers for sodeep! i like it.

I have a sproc I'm going to call from a job to do the logging I described.
Just have one challenge left. How do you turn the results of a DBCC command into a table you can select from?
Here's the problem:

declare @instanceID int
set @instanceID=(select max(BLK_InstanceID)+1 from admin.dbo.MonitorBlocks)

--1) Log participating records to the table
insert MonitorBlocks (BLK_Spid,BLK_BlockBySpid,BLK_HostName,BLK_ProgramName,BLK_CommandType,BLK_CommandText,BLK_InstanceID,BLK_CreateDate)
select spid,blocked,hostname,[program_name],cmd,'',@instanceID,getdate()
from master.dbo.sysprocesses p
where BLK_BlockBySpid<>0
or exists (select * from master.dbo.sysprocesses a where a.spid>0 and a.spid=BLK_BlockBySpid)

--2) Update CmdText
declare @nextSpid int
declare @cmdText varchar(255)
while (select count(*) from MonitorBlocks where BLK_InstanceID=@instanceID and BLK_CommandText='')>0
begin
set @nextSpid=(select top 1 BLK_Spid from MonitorBlocks where BLK_InstanceID=@instanceID and BLK_CommandText='')
set @cmdText=(select EventInfo from DBCC inputbuffer(@nextSpid) )
update MonitorBlocks
set BLK_CommandText=@cmdText
where BLK_InstanceID=@instanceID
and BLK_Spid=@nextSpid
end

coolerbob
Aged Yak Warrior

841 Posts

Posted - 2008-04-24 : 11:36:01

And if you want to create the table first:

use [admin]

BEGIN TRANSACTION
SET QUOTED_IDENTIFIER ON
SET ARITHABORT ON
SET NUMERIC_ROUNDABORT OFF
SET CONCAT_NULL_YIELDS_NULL ON
SET ANSI_NULLS ON
SET ANSI_PADDING ON
SET ANSI_WARNINGS ON
COMMIT
BEGIN TRANSACTION
GO
CREATE TABLE dbo.MonitorBlocks
(
BLK_ID int NOT NULL IDENTITY (1, 1),
BLK_Spid int NOT NULL,
BLK_BlockBySpid int NOT NULL,
BLK_HostName varchar(50) NOT NULL,
BLK_ProgramName varchar(50) NOT NULL,
BLK_CommandType varchar(50) NOT NULL,
BLK_CommandText varchar(50) NOT NULL,
BLK_InstanceID int NOT NULL
) ON [PRIMARY]
GO
ALTER TABLE dbo.MonitorBlocks ADD CONSTRAINT
DF_MonitorBlocks_BLK_BlockBySpid DEFAULT 0 FOR BLK_BlockBySpid
GO
ALTER TABLE dbo.MonitorBlocks ADD CONSTRAINT
DF_MonitorBlocks_BLK_HostName DEFAULT '' FOR BLK_HostName
GO
ALTER TABLE dbo.MonitorBlocks ADD CONSTRAINT
DF_MonitorBlocks_BLK_ProgramName DEFAULT '' FOR BLK_ProgramName
GO
ALTER TABLE dbo.MonitorBlocks ADD CONSTRAINT
DF_MonitorBlocks_BLK_CommandType DEFAULT '' FOR BLK_CommandType
GO
ALTER TABLE dbo.MonitorBlocks ADD CONSTRAINT
DF_MonitorBlocks_BLK_CommandText DEFAULT '' FOR BLK_CommandText
GO
ALTER TABLE dbo.MonitorBlocks ADD CONSTRAINT
DF_MonitorBlocks_BLK_InstanceID DEFAULT 0 FOR BLK_InstanceID
GO
ALTER TABLE dbo.MonitorBlocks ADD CONSTRAINT
PK_MonitorBlocks PRIMARY KEY CLUSTERED
(
BLK_ID
) WITH( STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]

GO
CREATE NONCLUSTERED INDEX IX_MonitorBlocks_InstanceID ON dbo.MonitorBlocks
(
BLK_InstanceID DESC
) WITH( PAD_INDEX = ON, FILLFACTOR = 99, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
GO
COMMIT

BEGIN TRANSACTION
SET QUOTED_IDENTIFIER ON
SET ARITHABORT ON
SET NUMERIC_ROUNDABORT OFF
SET CONCAT_NULL_YIELDS_NULL ON
SET ANSI_NULLS ON
SET ANSI_PADDING ON
SET ANSI_WARNINGS ON
COMMIT
BEGIN TRANSACTION
GO
ALTER TABLE dbo.MonitorBlocks ADD
BLK_CreateDate datetime NOT NULL CONSTRAINT DF_MonitorBlocks_BLK_CreateDate DEFAULT getdate()
GO
COMMIT

sodeep
Master Smack Fu Yak Hacker

7174 Posts

Posted - 2008-04-24 : 11:59:28

Here is what you need:

declare @spid int, @counter int
create table ##temp_blocked_spids
(id int identity (1,1) primary key, spid int, blocked int,
hostname nchar(256), program_name nchar(256), loginame nchar(256))
create table ##ib_info
(id int identity (1,1) primary key, spid int, eventtype varchar(1000),
parameters varchar(1000), inputbuffer varchar(2000))
insert into ##temp_blocked_spids (spid, blocked, hostname, program_name, loginame)
select spid, blocked, rtrim(hostname), rtrim(program_name), rtrim(loginame)
from sysprocesses
where (blocked != 0 and spid !=blocked) or (spid in (select distinct blocked from sysprocesses where blocked !=0 and spid !=blocked))
group by spid, blocked, hostname, program_name, loginame
order by spid
set nocount on
declare ibuffer cursor fast_forward for
select spid from ##temp_blocked_spids
open ibuffer
fetch next from ibuffer into @spid
while (@@fetch_status != -1)
begin
insert into ##ib_info (eventtype, parameters, inputbuffer)
exec ('dbcc inputbuffer (' + @spid + ')')
fetch next from ibuffer into @spid
end
deallocate ibuffer
set nocount off
-- If there are entries in the table, send an email.
if (select count(*) from ##temp_blocked_spids) > 0
begin
EXEC msdb.dbo.sp_send_dbmail
@profile_name = 'name',
@recipients = 'email',
@query = 'select left(s.spid,4) as spid, left(s.blocked,4) as blocked, left(d.inputbuffer,52) as inputbuffer,
left(s.program_name,10) as program_name, left(s.loginame,10) as login_name,left(s.hostname,15) as host_name
from ##temp_blocked_spids s join ##ib_info d on (s.id = d.id)',
@body = 'The following spids are involved in blocking',
@subject = 'Blocking on ---' ;
end
-- Drop the temporary tables.
drop table ##temp_blocked_spids
drop table ##ib_info

coolerbob
Aged Yak Warrior

841 Posts

Posted - 2008-04-24 : 12:22:55

insert into ##ib_info (eventtype, parameters, inputbuffer)
exec ('dbcc inputbuffer (' + @spid + ')')

That's what I was after
thanks!

Here's the finished product:

declare @instanceID int
set @instanceID=(select isnull(max(BLK_InstanceID)+1,0) from admin.dbo.MonitorBlocks)

declare @table table (eventtype varchar(50), parameters varchar(50), EventInfo varchar(50))

--1) Log participating records to the table
insert MonitorBlocks (BLK_Spid,BLK_BlockBySpid,BLK_HostName,BLK_ProgramName,BLK_CommandType,BLK_CommandText,BLK_InstanceID,BLK_CreateDate)
select spid,blocked,hostname,[program_name],cmd,'',@instanceID,getdate()
from master.dbo.sysprocesses p
where blocked<>0
or exists (select * from master.dbo.sysprocesses a where a.spid>0 and p.spid=a.blocked)

--2) Update CmdText
declare @nextSpid int
declare @cmdText varchar(255)
while (select count(*) from MonitorBlocks where BLK_InstanceID=@instanceID and BLK_CommandText='' and BLK_Processed=0)>0
begin
set @nextSpid=(select top 1 BLK_Spid from MonitorBlocks where BLK_InstanceID=@instanceID and BLK_CommandText='' and BLK_Processed=0)

delete from @table
insert into @table (eventtype, parameters, EventInfo)
exec ('dbcc inputbuffer (' + @nextSpid + ')')

set @cmdText=(select top 1 EventInfo from @table )

update MonitorBlocks
set BLK_CommandText=isnull(@cmdText,''),
BLK_Processed=1
where BLK_InstanceID=@instanceID
and BLK_Spid=@nextSpid
end

Ola Hallengren
Starting Member

33 Posts

Posted - 2008-04-25 : 12:58:30

I think that you should have a look at the 'Blocked Process Report' events.

You can define that you would like to generate a 'Blocked Process Report' if a process is blocked for more than a number of seconds.

The threshold is set with a sp_configure option.
http://msdn2.microsoft.com/en-us/library/ms181150.aspx

The 'Blocked Process Report' contains information about the blocked and blocking process.
http://msdn2.microsoft.com/en-us/library/ms191168.aspx

Then you could capture these events using SQL Trace or Event Notifications. If you're using Event Notifications you could have the events inserted into a table.
http://msdn2.microsoft.com/en-us/library/ms190427.aspx

Ola Hallengren
http://ola.hallengren.com

coolerbob
Aged Yak Warrior

841 Posts

Posted - 2008-04-28 : 03:51:40

Wow! Thanks Ola! What I wrote is working quite well, but it's nice to see something more "official". I'll implement this too and compare the results. Thanks again for posting this. This is the level of replies that makes this site so good.

jen
Master Smack Fu Yak Hacker

4110 Posts

Posted - 2008-04-28 : 05:39:13

instead of dbcc inputbuffer.. another alternative is
i didn't post the table schema, just check out which information you want to save...


CREATE procedure [dbo].[GetBlocks]      
 @dbname nvarchar(60)=null      
as      
      
set nocount on      
    
 declare @datestamp datetime      
    
 set @datestamp=getdate()   
     
 insert into blocks(datestamp,spid,blockingspid,cpu,physical_io,mempages,logintime,login_name      
 ,waittimeinsec,lastwaittype,waitresource,numofopentran,currentcommand,sqlstatement,blockingcommand      
 ,blockingstatement,lockedobject      
  ,lastbatch)      
 select @datestamp,spid.spid,spid.blocked,spid.cpu,spid.physical_io,spid.memusage as [Mem_Pages]      
  ,spid.login_time,spid.loginame      
  ,spid.waittime/1000 as [WaitTime(s)]      
  ,spid.lastwaittype      
  ,spid.waitresource       
  ,spid.open_tran      
  ,spid.cmd [CurrentCommand]      
  ,(select text from sys.dm_exec_sql_text(spid.sql_handle)) as sqlstatement      
  ,case when blockingspid.cmd='Awaiting Command' then 'OpenTran Waiting for Commit'      
   else blockingspid.cmd end as [BlockingCommand]      
  ,(select text from sys.dm_exec_sql_text(blockingspid.sql_handle)) as blockingstatement      
  ,locks.resource_type + ':' + convert(varchar(100),locks.resource_associated_entity_id) + ':' + locks.request_status + ':' + locks.request_mode     
  as [ResourceType:LockedTable:Status:Mode]      
  ,spid.last_batch       
 from master..sysprocesses SPID      
  join master..sysprocesses BlockingSPID on spid.blocked=blockingspid.spid       
  join sys.dm_tran_locks locks on locks.request_session_id=spid.spid    
 where (spid.dbid=coalesce(db_id(@dbname),spid.dbid)     
   and spid.dbid not in (select database_id from sys.databases where name in ('master','model','tempdb','msdb'))    
  )    
 and spid.spid<>@@spid  
 and spid.spid<>blockingspid.spid    
 and spid.blocked>0   
 and locks.request_mode not in ('S','Sch-S')  
 and not exists (select * from srvadmin..blocks where spid=spid.spid and currentcommand=spid.cmd      
  and NumOfOpenTran=spid.open_tran and lastbatch=spid.last_batch)

--------------------
keeping it simple...

coolerbob
Aged Yak Warrior

841 Posts

Posted - 2008-04-30 : 05:49:58

Thanks Jen,

I've not had much luck getting sensible results from dbcc inputbuffer. It's been spurious.
So I'll try this too along with Ola's approach and let you know how I get on.

What's this though?
srvadmin..blocks

coolerbob
Aged Yak Warrior

841 Posts

Posted - 2008-05-01 : 11:59:18

What do I put where the question mark is? I dont know the exact event name for this:

CREATE EVENT NOTIFICATION DeadlockNotification
ON SERVER
FOR ?
TO SERVICE 'NotifyService', '8140a771-3c4b-4479-8ac0-81008ab17984' ;

quote:
Originally posted by Ola Hallengren

I think that you should have a look at the 'Blocked Process Report' events.

You can define that you would like to generate a 'Blocked Process Report' if a process is blocked for more than a number of seconds.

The threshold is set with a sp_configure option.
http://msdn2.microsoft.com/en-us/library/ms181150.aspx

The 'Blocked Process Report' contains information about the blocked and blocking process.
http://msdn2.microsoft.com/en-us/library/ms191168.aspx

Then you could capture these events using SQL Trace or Event Notifications. If you're using Event Notifications you could have the events inserted into a table.
http://msdn2.microsoft.com/en-us/library/ms190427.aspx

Ola Hallengren
http://ola.hallengren.com

Ola Hallengren
Starting Member

33 Posts

Posted - 2008-05-01 : 12:19:07

You should have a look at the BLOCKED_PROCESS_REPORT and DEADLOCK_GRAPH trace event types. You could put both in the same event notification with a comma in between.
http://msdn.microsoft.com/en-us/library/ms187476.aspx

Ola Hallengren
http://ola.hallengren.com

coolerbob
Aged Yak Warrior

841 Posts

Posted - 2008-05-02 : 04:39:32

Brilliant, thanks.
Two other questions:

When I tried calling this, I gave up after 90 seconds. Any reason you know of why it should take so long?
ALTER DATABASE MyDB
SET ENABLE_BROKER;
GO
(It's in this sample C:\Program Files\Microsoft SQL Server\90\Samples\Engine\Administration\EventNotifications\Scripts\)

2nd, you say I could log the results to a table. What would that sql look like?
Would you put a INSERT statement somewhere in here like this? (I would test this myself if it wasn't for the set ENABLE_BROKER problem I'm having):

select * into NewTable from
WAITFOR (
RECEIVE
CASE
WHEN validation = 'X' THEN CAST(message_body as XML)
ELSE NULL
END AS message_body
,*
FROM [AdventureWorks].[dbo].[Notify-Queue]
), TIMEOUT 10000

TRACEYSQL
Aged Yak Warrior

594 Posts

Posted - 2008-05-02 : 15:42:52

Here is the deadlock...
http://msdn.microsoft.com/en-us/library/ms186385.aspx

Ola Hallengren
Starting Member

33 Posts

Posted - 2008-05-03 : 08:22:22

Here is some code that I'm using.

-- First make sure that service broker is enabled in the current database.
SELECT [name], is_broker_enabled FROM sys.databases

-- Create an audit table
CREATE TABLE dbo.Audit ( AuditID int NOT NULL IDENTITY,
PostTime datetime NULL,
EventType sysname NULL,
LoginName sysname NULL,
UserName sysname NULL,
ServerName sysname NULL,
DatabaseName sysname NULL,
ObjectType sysname NULL,
SchemaName sysname NULL,
ObjectName sysname NULL,
EventData xml NULL,
CONSTRAINT PK_Audit PRIMARY KEY CLUSTERED (AuditID ASC))
GO

CREATE PROCEDURE dbo.AuditReceive

AS

BEGIN TRY

DECLARE @AuditMessage TABLE (EventData xml)

BEGIN TRANSACTION;

RECEIVE CAST(message_body AS XML)
FROM dbo.AuditQueue
INTO @AuditMessage

INSERT INTO dbo.Audit (PostTime, EventType, LoginName, UserName, ServerName, DatabaseName, ObjectType, SchemaName, ObjectName, EventData)
SELECT CAST(EventData.query('data(//PostTime)') AS varchar(23)),
NULLIF(CAST(EventData.query('data(//EventType)') AS sysname),''),
NULLIF(CAST(EventData.query('data(//LoginName)') AS sysname),''),
NULLIF(CAST(EventData.query('data(//UserName)') AS sysname),''),
NULLIF(CAST(EventData.query('data(//ServerName)') AS sysname),''),
NULLIF(CAST(EventData.query('data(//DatabaseName)') AS sysname),''),
NULLIF(CAST(EventData.query('data(//ObjectType)') AS sysname),''),
NULLIF(CAST(EventData.query('data(//SchemaName)') AS sysname),''),
NULLIF(CAST(EventData.query('data(//ObjectName)') AS sysname),''),
EventData
FROM @AuditMessage

COMMIT TRANSACTION

END TRY

BEGIN CATCH

ROLLBACK TRANSACTION

END CATCH

GO

-- Create a queue to receive messages
CREATE QUEUE dbo.AuditQueue
WITH STATUS = ON, ACTIVATION (STATUS = ON, PROCEDURE_NAME = dbo.AuditReceive, MAX_QUEUE_READERS = 1, EXECUTE AS Owner)
GO

-- Create a service on the queue that references the event notifications contract
CREATE SERVICE AuditService
ON QUEUE dbo.AuditQueue ([http://schemas.microsoft.com/SQL/Notifications/PostEventNotification])
GO

-- Create a route on the service to define the address to which Service Broker sends messages for the service
CREATE ROUTE AuditRoute
WITH SERVICE_NAME = 'AuditService', ADDRESS = 'LOCAL'
GO

-- Create the event notification
CREATE EVENT NOTIFICATION AuditEventNotification
ON SERVER FOR
DDL_TABLE_EVENTS
TO SERVICE 'AuditService', 'current database'

Ola Hallengren
Starting Member

33 Posts

Posted - 2008-05-03 : 08:26:59

>When I tried calling this, I gave up after 90 seconds. Any reason you know of why it should take so long?

I think that there should be no other connections against the database, when you execute the command. This should be an instant operation.

Subscribe to SQLTeam.com

SQLTeam.com Articles via RSS

SQLTeam.com Weblog via RSS

- Advertisement -

Resources