如何有效抓取SQL Server的BLOCKING信息

转自：微软亚太区数据库技术支持组官方博客

http://blogs.msdn.com/b/apgcdsd/archive/2011/12/12/sql-server-blocking.aspx

SQL Server允许并发操作，BLOCKING是指在某一操作没有完成之前，其他操作必须等待，以便于保证数据的完整性。BLOCKING的解决方法要查看BLOCKING的头是什么，为什么BLOCKING头上的语句执行的很慢。通常来讲只要我们能找到BLOCKING头上的语句，我们总能够想出各种各种的办法，来提升性能，缓解或解决BLOCKING的问题。

但是问题的关键是，我们不知道BLOCKING什么时候会发生。用户跟我们抱怨数据库性能很差，等我们连上数据库去查看的时候，那时候有可能BLOCKING可能就已经过去了。性能又变好了。或者由于问题的紧急性，我们直接重新启动服务器以恢复运营。但是问题并没有最终解决，我们不知道下次问题会在什么时候发生。

BLOCKING问题的后果比较严重。因为终端用户能直接体验到。他们提交一个订单的时候，无论如何提交不上去，通常几秒之内能完成的一个订单提交，甚至要等待十几分钟，才能提交完成。更有甚者，极严重的BLOCKING能导致SQL Server停止工作。如下面的SQL ERRORLOG所表示, 在短短的几分钟之内，SPID数据从158增长到694, 并马上导致SQL Server打了一个dump, 停止工作。我们很容易推断出问题的原因是由于BLOCKING导致的，但是我们无法得知BLOCKING HEADER是什么，我们必须要等下次问题重现时，辅之以工具，才能得知BLOCKING HEADER在做什么事情。如果信息抓取时机不对，我们可能要等问题发生好几次，才能抓到。这时候，客户和经理就会有抱怨了。因为我们的系统是生产系统，问题每发生一次，都会对客户带来损失。

2011-06-01 16:22:30.98 spid1931 Alert There are 158 Active database sessions which is too high.

2011-06-01 16:23:31.16 spid3248 Alert There are 342 Active database sessions which is too high.

2011-06-01 16:24:31.06 spid3884 Alert There are 517 Active database sessions which is too high.

2011-06-01 16:25:31.08 spid3688 Alert There are 694 Active database sessions which is too high.

2011-06-01 16:26:50.93 Server Using 'dbghelp.dll' version '4.0.5'

2011-06-01 16:26:50.97 Server **Dump thread - spid = 0, EC = 0x0000000000000000

2011-06-01 16:26:50.97 Server ***Stack Dump being sent to D:\MSSQL10.INSTANCE\MSSQL\LOG\SQLDump0004.txt

2011-06-01 16:26:50.97 Server * *******************************************************************************

2011-06-01 16:26:50.97 Server *

2011-06-01 16:26:50.97 Server * BEGIN STACK DUMP:

2011-06-01 16:26:50.97 Server * 06/01/11 16:26:50 spid 4124

2011-06-01 16:26:50.97 Server *

2011-06-01 16:26:50.97 Server * Deadlocked Schedulers

2011-06-01 16:26:50.97 Server *

2011-06-01 16:26:50.97 Server * *******************************************************************************

2011-06-01 16:26:50.97 Server * -------------------------------------------------------------------------------

2011-06-01 16:26:50.97 Server * Short Stack Dump

2011-06-01 16:26:51.01 Server Stack Signature for the dump is 0x0000000000000258

BLOCKING的信息抓取有很多种方法。这里罗列了几种。并且对每种分析它的优缺点。以便我们选择。在枚举方法之前，我们先简单演示一下BLOCKING.

我们首先创建一个测试表:

DROP TABLE [TESTTABLE]

CREATE TABLE [dbo] . [TESTTABLE] (

[ID] [int] NULL,

[NAME] [nvarchar] ( 50 ) NULL

)

INSERT INTO TESTTABLE VALUES ( 1 , 'aaaa' )

然后打开一个查询窗口，执行下面的语句, 该语句修改一行数据，并等待3分钟，然后在结束transaction

BEGIN TRANSACTION

UPDATE TESTTABLE SET [NAME] = 'bbbb' WHERE [ID] = 1

WAITFOR DELAY '00:03:00'

COMMIT TRANSACTION

这时候，如果打开另外一个查询窗口，执行下面的语句，下面的语句就会被BLOCK住。

UPDATE TESTTABLE SET [NAME] = 'cccc' WHERE [ID] = 1

方法一, 抓取SQL Profiler

======================

SQL Profiler里面包含大量的信息。其中有一个事件在Errors and Warnings->Blocked Process Report专门用来获得blocking的情况。但是因为信息量比较大，而且我们并不能很好的估算在什么时候会产生blocking，另外在生产环境使用Profiler, 对性能可能会有影响，所以SQL Profiler并不是最合适的工具。我们在这里并不对它赘述。

方法二, 执行查询

================

如果我们检查问题的时候，blocking还存在，那么，我们可以直接可以运行几个查询，得知BLOCKING HEADER的信息

SELECT * FROM sys . sysprocesses where spid > 50

上述查询只是告诉我们，BLOCKING HEADER的头是SPID=53, 但是并没有告诉我们SPID=53在做什么事情。我们可以用下面的查询，得到SPID=53的信息

DBCC INPUTBUFFER ( 53 )

我们可以把上述的两个查询合并起来，用下面的查询:

SELECT SPID = p . spid ,

DBName = convert ( CHAR ( 20 ), d . name ),

ProgramName = program_name ,

LoginName = convert ( CHAR ( 20 ), l . name ),

HostName = convert ( CHAR ( 20 ), hostname ),

Status = p . status ,

BlockedBy = p . blocked ,

LoginTime = login_time ,

QUERY = CAST ( TEXT AS VARCHAR ( MAX ))

FROM MASTER . dbo . sysprocesses p

INNER JOIN MASTER . dbo . sysdatabases d

ON p . dbid = d . dbid

INNER JOIN MASTER . dbo . syslogins l

ON p . sid = l . sid

CROSS APPLY sys . dm_exec_sql_text ( sql_handle )

WHERE p . blocked = 0

AND EXISTS ( SELECT 1

FROM MASTER .. sysprocesses p1

WHERE p1 . blocked = p . spid )

这样，一次执行，就能告诉我们BLOCKING header的SPID信息，以及该SPID在做的语句。我们可以进一步研究该语句，以理解为什么该语句执行很慢。

用这个方法有一个缺点，就是使用的时候，要求BLOCKING是存在的。如果BLOCKING已经消失了，那么我们的方法就不管用了。

方法三,长期执行一个BLOCKING SCRIPT

==================================

因为我们通常无法知道BLOCKING什么时候会产生，所以通常的办法是我们长期运行一个BLOCKING SCRIPT, 这样，等下次发生的时候，我们就会有足够的信息。长期运行BLOCKING SCRIPT对性能基本上是没有影响的。因为我们每隔10秒钟抓取一次信息。缺点是，如果问题一个月才发生一次，那么，我们的BLOCKING日志信息会很大。所以这种方法适用于几天之内能重现问题。

运行方法如下:

如果要停止运行，我们按ctrl+c就可以了。

BLOCKING的信息存在log.out这个文件中

我们可以打开log.out这个文件, 会发现SPID 54被 SPID 53给Block住了。

而随后，我们可以看到SPID=53在做什么事情:

下面是BLOCKING SCRIPT的脚本, 我们可以把它存为blocking.sql

use master

while 1 = 1

begin

print 'Start time: ' + convert ( varchar ( 26 ), getdate (), 121 )

Print 'Running processes'

select spid , blocked , waittype , waittime , lastwaittype , waitresource , dbid , uid , cpu , physical_io , memusage , login_time , last_batch ,

open_tran , status , hostname , program_name , cmd , net_library , loginame

from sysprocesses

--where (kpid <> 0 ) or (spid < 51)

-- Change it if you only want to see the working processes

print '*********lockinfor***********'

select convert ( smallint , req_spid ) As spid ,

rsc_dbid As dbid ,

rsc_objid As ObjId ,

rsc_indid As IndId ,

substring ( v . name , 1 , 4 ) As Type ,

substring ( rsc_text , 1 , 16 ) as Resource ,

substring ( u . name , 1 , 8 ) As Mode ,

substring ( x . name , 1 , 5 ) As Status

from master . dbo . syslockinfo ,

master . dbo . spt_values v ,

master . dbo . spt_values x ,

master . dbo . spt_values u

where master . dbo . syslockinfo . rsc_type = v . number

and v . type = 'LR'

and master . dbo . syslockinfo . req_status = x . number

and x . type = 'LS'

and master . dbo . syslockinfo . req_mode + 1 = u . number

and u . type = 'L'

order by spid

print 'inputbuffer for running processes'

declare @spid varchar ( 6 )

declare ibuffer cursor fast_forward for

select cast ( spid as varchar ( 6 )) as spid from sysprocesses where spid > 50

open ibuffer

fetch next from ibuffer into @spid

while ( @@fetch_status != - 1 )

begin

print ''

print 'DBCC INPUTBUFFER FOR SPID ' + @spid

exec ( 'dbcc inputbuffer (' + @spid + ')' )

fetch next from ibuffer into @spid

end

deallocate ibuffer

waitfor delay '0:0:10'

End

这种方法的缺陷就是，log.out会比较巨大，会占用很大的空间，如果blocking一个月甚至更长时间才发生一次，那我们的这个方法就不太适宜。

方法四,我们用Agent Job来检查BLOCKING

=====================================

长期运行一个BLOCKING SCRIPT的缺点是我们每隔一段时间，去查询信息，但是大多数收集的信息是无用的。所以会导致日志文件巨大，对于一个生产系统来讲，磁盘空间满可不是个好事情，另外，有一些客户对于用命令行来长期运行TSQL脚本有所顾忌，所以我们做了一个改进。这次，我们只收集有用的信息。对于无用的信息我们不关注。这样能极大减少日志大小。

我们首先创建一个观察数据库，然后建立两张表格 Blocking_sysprocesses和Blocking_SQLText, 建立一个存储过程和一个Job, 该Job每隔一段时间去调用存储过程。只有发现有blocking的，我们才记录到表格Blocking_sysprocesses和Blocking_SQLText这两个表格中。如果跟blocking无关，我们就不对它进行记录。下面是TSQL语句:

CREATE DATABASE [MonitorBlocking]

USE [MonitorBlocking]

CREATE TABLE Blocking_sysprocesses (

[spid] smallint ,

[kpid] smallint ,

[blocked] smallint ,

[waitType] binary ( 2 ),

[waitTime] bigInt ,

[lastWaitType] nchar ( 32 ),

[waitResource] nchar ( 256 ),

[dbID] smallint ,

[uid] smallint ,

[cpu] int ,

[physical_IO] int ,

[memusage] int ,

[login_Time] datetime ,

[last_Batch] datetime ,

[open_Tran] smallint ,

[status] nchar ( 30 ),

[sid] binary ( 86 ),

[hostName] nchar ( 128 ),

[program_Name] nchar ( 128 ),

[hostProcess] nchar ( 10 ),

[cmd] nchar ( 16 ),

[nt_Domain] nchar ( 128 ),

[nt_UserName] nchar ( 128 ),

[net_Library] nchar ( 12 ),

[loginName] nchar ( 128 ),

[context_Info] binary ( 128 ),

[sqlHandle] binary ( 20 ),

[CapturedTimeStamp] datetime

)

CREATE TABLE [dbo] . [Blocking_SqlText] (

[spid] [smallint] ,

[sql_text] [nvarchar] ( 2000 ),

[Capture_Timestamp] [datetime]

)

CREATE PROCEDURE [dbo] . [checkBlocking]

BEGIN

SET NOCOUNT ON ;

SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED

declare @Duration int -- in milliseconds, 1000 = 1 sec

declare @now datetime

declare @Processes int

select @Duration = 100 -- in milliseconds, 1000 = 1 sec

select @Processes = 0

select @now = getdate ()

CREATE TABLE #Blocks_rg (

[spid] smallint ,

[kpid] smallint ,

[blocked] smallint ,

[waitType] binary ( 2 ),

[waitTime] bigInt ,

[lastWaitType] nchar ( 32 ),

[waitResource] nchar ( 256 ),

[dbID] smallint ,

[uid] smallint ,

[cpu] int ,

[physical_IO] int ,

[memusage] int ,

[login_Time] datetime ,

[last_Batch] datetime ,

[open_Tran] smallint ,

[status] nchar ( 30 ),

[sid] binary ( 86 ),

[hostName] nchar ( 128 ),

[program_Name] nchar ( 128 ),

[hostProcess] nchar ( 10 ),

[cmd] nchar ( 16 ),

[nt_Domain] nchar ( 128 ),

[nt_UserName] nchar ( 128 ),

[net_Library] nchar ( 12 ),

[loginName] nchar ( 128 ),

[context_Info] binary ( 128 ),

[sqlHandle] binary ( 20 ),

[CapturedTimeStamp] datetime

)

INSERT INTO #Blocks_rg

SELECT

[spid] ,

[kpid] ,

[blocked] ,

[waitType] ,

[waitTime] ,

[lastWaitType] ,

[waitResource] ,

[dbID] ,

[uid] ,

[cpu] ,

[physical_IO] ,

[memusage] ,

[login_Time] ,

[last_Batch] ,

[open_Tran] ,

[status] ,

[sid] ,

[hostName] ,

[program_name] ,

[hostProcess] ,

[cmd] ,

[nt_Domain] ,

[nt_UserName] ,

[net_Library] ,

[loginame] ,

[context_Info] ,

[sql_Handle] ,

@now as [Capture_Timestamp]

FROM master. . sysprocesses where blocked <> 0

AND waitTime > @Duration

SET @Processes = @@rowcount

INSERT into #Blocks_rg

SELECT

src . [spid] ,

src . [kpid] ,

src . [blocked] ,

src . [waitType] ,

src . [waitTime] ,

src . [lastWaitType] ,

src . [waitResource] ,

src . [dbID] ,

src . [uid] ,

src . [cpu] ,

src . [physical_IO] ,

src . [memusage] ,

src . [login_Time] ,

src . [last_Batch] ,

src . [open_Tran] ,

src . [status] ,

src . [sid] ,

src . [hostName] ,

src . [program_name] ,

src . [hostProcess] ,

src . [cmd] ,

src . [nt_Domain] ,

src . [nt_UserName] ,

src . [net_Library] ,

src . [loginame] ,

src . [context_Info] ,

src . [sql_Handle]

, @now as [Capture_Timestamp]

FROM master. . sysprocesses src inner join #Blocks_rg trgt

on trgt . blocked = src . [spid]

if @Processes > 0

BEGIN

INSERT [dbo] . [Blocking_sysprocesses]

SELECT * from #Blocks_rg

DECLARE @SQL_Handle binary ( 20 ), @SPID smallInt ;

DECLARE cur_handle CURSOR FOR SELECT sqlHandle , spid FROM #Blocks_rg ;

OPEN cur_Handle

FETCH NEXT FROM cur_handle INTO @SQL_Handle , @SPID

WHILE ( @@FETCH_STATUS = 0 )

BEGIN

INSERT [dbo] . [Blocking_SqlText]

SELECT @SPID , CONVERT ( nvarchar ( 4000 ), [text] ) , @now as [Capture_Timestamp] from :: fn_get_sql ( @SQL_Handle )

FETCH NEXT FROM cur_handle INTO @SQL_Handle , @SPID

END

CLOSE cur_Handle

DEALLOCATE cur_Handle

END

DROP table #Blocks_rg

END

USE msdb ;

EXEC dbo . sp_add_job

@job_name = N'MonitorBlocking' ;

EXEC sp_add_jobstep

@job_name = N'MonitorBlocking' ,

@step_name = N'execute blocking script' ,

@subsystem = N'TSQL' ,

@command = N'exec checkBlocking' ,

@database_name = N'MonitorBlocking';

EXEC sp_add_jobSchedule

@name = N'ScheduleBlockingCheck' ,

@job_name = N'MonitorBlocking' ,

@freq_type = 4 , -- daily

@freq_interval = 1 ,

@freq_subday_type = 4 ,

@freq_subday_interval = 1

EXEC sp_add_jobserver @job_name = N'MonitorBlocking' , @server_name = N'(local)'

当Blocking发生一段时间后，我们可以查询下面的两个表格，以得知当时问题发生时的blocking信息:

use MonitorBlocking

SELECT * from Blocking_sqlText

SELECT * FROM Blocking_sysprocesses

如何有效抓取SQL Server的BLOCKING信息

更多文章、技术交流、商务合作、联系博主

微信扫码或搜索：z360901061

微信扫一扫加我为好友

QQ号联系： 360901061

您的支持是博主写作最大的动力，如果您喜欢我的文章，感觉我的文章对您有帮助，请用微信扫描下面二维码支持博主2元、5元、10元、20元等您想捐的金额吧，狠狠点击下面给点支持吧，站长非常感激您！手机微信长按不能支付解决办法：请将微信支付二维码保存到相册，切换到微信，然后点击微信右上角扫一扫功能，选择支付二维码完成支付。

【本文对您有帮助就好】元

2元

5元

10元

20元

自定义