如何有效抓取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.97Server * BEGIN STACK DUMP:

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

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.

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

DROPTABLE[TESTTABLE]

GO

CREATETABLE[dbo].[TESTTABLE](

[ID] [int]NULL,

[NAME] [nvarchar](50)NULL

)

GO

INSERTINTOTESTTABLEVALUES(1,'aaaa')

GO

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

BEGINTRANSACTION

UPDATETESTTABLESET[NAME]='bbbb'WHERE[ID]=1

WAITFORDELAY'00:03:00'

COMMITTRANSACTION

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

UPDATETESTTABLESET[NAME]='cccc'WHERE[ID]=1

方法一,抓取SQL Profiler

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

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

方法二,执行查询

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

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

SELECT*FROMsys.sysprocesseswherespid>50

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

DBCCINPUTBUFFER(53)

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

SELECTSPID=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(TEXTASVARCHAR(MAX))

FROMMASTER.dbo.sysprocessesp

INNERJOINMASTER.dbo.sysdatabasesd

ONp.dbid=d.dbid

INNERJOINMASTER.dbo.sysloginsl

ONp.sid=l.sid

CROSSAPPLYsys.dm_exec_sql_text(sql_handle)

WHEREp.blocked=0

ANDEXISTS(SELECT1

FROMMASTER..sysprocessesp1

WHEREp1.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

usemaster

go

while1=1

begin

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

Print'Running processes'

selectspid,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

fromsysprocesses

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

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

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

selectconvert(smallint,req_spid)Asspid,

rsc_dbidAsdbid,

rsc_objidAsObjId,

rsc_indidAsIndId,

substring(v.name,1,4)AsType,

substring(rsc_text,1,16)asResource,

substring(u.name,1,8)AsMode,

substring(x.name,1,5)AsStatus

frommaster.dbo.syslockinfo,

master.dbo.spt_values v,

master.dbo.spt_values x,

master.dbo.spt_values u

wheremaster.dbo.syslockinfo.rsc_type=v.number

andv.type='LR'

andmaster.dbo.syslockinfo.req_status=x.number

andx.type='LS'

andmaster.dbo.syslockinfo.req_mode+1=u.number

andu.type='L'

orderbyspid

print'inputbuffer for running processes'

declare@spidvarchar(6)

declareibuffercursorfast_forwardfor

selectcast(spidasvarchar(6))asspidfromsysprocesseswherespid>50

openibuffer

fetchnextfromibufferinto@spid

while(@@fetch_status!=-1)

begin

print''

print'DBCC INPUTBUFFER FOR SPID '+@spid

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

fetchnextfromibufferinto@spid

end

deallocateibuffer

waitfordelay'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语句:

CREATEDATABASE[MonitorBlocking]

GO

USE[MonitorBlocking]

GO

CREATETABLEBlocking_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

)

GO

CREATETABLE[dbo].[Blocking_SqlText](

[spid] [smallint],

[sql_text] [nvarchar](2000),

[Capture_Timestamp] [datetime]

)

GO

CREATEPROCEDURE[dbo].[checkBlocking]

AS

BEGIN

SETNOCOUNTON;

SETTRANSACTIONISOLATIONLEVELREADUNCOMMITTED

declare@Durationint-- in milliseconds, 1000 = 1 sec

declare@nowdatetime

declare@Processesint

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

select@Processes=0

select@now=getdate()

CREATETABLE#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

)

INSERTINTO#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],

@nowas[Capture_Timestamp]

FROMmaster..sysprocesseswhereblocked<>0

ANDwaitTime>@Duration

SET@Processes=@@rowcount

INSERTinto#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]

,@nowas[Capture_Timestamp]

FROMmaster..sysprocessessrcinnerjoin#Blocks_rg trgt

ontrgt.blocked=src.[spid]

if@Processes>0

BEGIN

INSERT[dbo].[Blocking_sysprocesses]

SELECT*from#Blocks_rg

DECLARE@SQL_Handlebinary(20),@SPIDsmallInt;

DECLAREcur_handleCURSORFORSELECTsqlHandle,spidFROM#Blocks_rg;

OPENcur_Handle

FETCHNEXTFROMcur_handleINTO@SQL_Handle,@SPID

WHILE(@@FETCH_STATUS=0)

BEGIN

INSERT[dbo].[Blocking_SqlText]

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

FETCHNEXTFROMcur_handleINTO@SQL_Handle,@SPID

END

CLOSEcur_Handle

DEALLOCATEcur_Handle

END

DROPtable#Blocks_rg

END

GO

USEmsdb;

GO

EXECdbo.sp_add_job

@job_name=N'MonitorBlocking';

GO

EXECsp_add_jobstep

@job_name=N'MonitorBlocking',

@step_name=N'execute blocking script',

@subsystem=N'TSQL',

@command=N'exec checkBlocking',

@database_name=N'MonitorBlocking';

GO

EXECsp_add_jobSchedule

@name=N'ScheduleBlockingCheck',

@job_name=N'MonitorBlocking',

@freq_type=4,-- daily

@freq_interval=1,

@freq_subday_type=4,

@freq_subday_interval=1

EXECsp_add_jobserver@job_name=N'MonitorBlocking',@server_name=N'(local)'

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

useMonitorBlocking

GO

SELECT*fromBlocking_sqlText

SELECT*FROMBlocking_sysprocesses