SQLSERVER排查阻塞

1、但是问题的关键是，我们不知道BLOCKIN御么时候会发生。用户跟我们抱怨数据库性能很差，等我们连上数据库去查看的时候，那时候有可能BLOCKIN能就已经过去了。性能又变好了。或者由于问题的紧急性，我们直接重新启动服务器以恢复运营。但是问题并没有最终解决，我们不知道下次问题会在什么时候发生。BLOCKIN制题的后果比较严重。因为终端用户能直接体验到。他们提交一个订单的时候，无论如何提交不上去，通常几秒之内能完成的一个订单提交，甚至要等待十几分钟，才能提交完成。更有甚者，极严重的BLOCKINGS导致SQLServer停止工作。如下面的SQLERRORLOGS示，在短短的几分钟之内，SPID数据从

2、158增长到694,并马上导致SQLServer打了一个dump,停止工作。我们很容易推断出问题的原因是由于BLOCKIN再致的，但是我们无法得知BLOCKINGHEADE暖什么，我们必须要等下次问题重现时，辅之以工具，才能得知BLOCKINGHEADERS做什么事情。如果信息抓取时机不对，我们可能要等问题发生好几次，才能抓到。这时候，客户和经理就会有抱怨了。因为我们的系统是生产系统，问题每发生一次，都会对客户带来损失。2011-06-01 16:22: spid19312011-06-01 16:23: spid32482011-06-01 16:24: spid38842011-06-01

3、 16:25: spid3688AlertThereare158Activedatabasesessionswhichistoohigh.AlertThereare342Activedatabasesessionswhichistoohigh.AlertThereare517Activedatabasesessionswhichistoohigh.AlertThereare694Activedatabasesessionswhichistoohigh.2011-06-01 16:26: ServerUsing '' version2011-06-01 16:26: Server

4、*Dump thread - spid = 0, EC = 0x00000000000000002011-06-01 16:26: Server2011-06-01 16:26: Server2011-06-01 16:26: Server2011-06-01 16:26: ServerBEGIN STACK DUMP:2011-06-01 16:26: Server06/01/11 16:26:50 spid 41242011-06-0116:26: Server2011-06-0116:26: Server* Deadlocked Schedulers2011-06-0116:26: Se

5、rver2011-06-0116:26: Server*2011-06-0116:26:Server2011-06-01 16:26: Server* Short Stack Dump2011-06-01 16:26: ServerStackSignatureforthedumpis0x0000000000000258BLOCKING：信息抓取有很多种方法。这里罗列了几种。并且对每种分析它的优缺点。以便我们选择。在枚举方法之前，我们先简单演示一下BLOCKING.我们首先创建一个测试表DROPTABLETESTTABLEGOCREATETABLEdbo.TESTTABLE(IDintNULL,

6、NAMEnvarchar(50)NULL)GOINSERTINTOTESTTABLEVALUES(1,'aaaa')GO然后打开一个查询窗口，执行下面的语句,该语句修改一行数据，并等待3分钟，然后在结束transactionBEGINTRANSACTIONUPDATETESTTABLESETNAME='bbbb'WHEREID=1WAITFORDELAY'00:03:00'COMMITTRANSACTION这时候，如果打开另外一个查询窗口，执行下面的语句，下面的语句就会被BLOCK住。WHEREID = 1UPDATETESTTABLESETNA

7、ME='cccc'方法一,抓取SQLProfilerSQLProfiler里面包含大量的信息。其中有一个事件在ErrorsandWarnings->BlockedProcessReport专门用来获得blocking的情况。但是因为信息量比较大，而且我们并不能很好的估算在什么时候会产生blocking，另外在生产环境使用Profiler,对性能可能会有影响，所以SQLProfiler并不是最合适的工具。我们在这里并不对它赘述。方法二,执行查询如果我们检查问题的时候，blocking还存在，那么，我们可以直接可以运行几个查询，得知BLOCKINGHEADER言息SELECT

8、*FROMwherespid>50上述查询只是告诉我们，BLOCKINGHEADERS是SPID=53，但是并没有告诉我们SPID=53在做什么事情。我们可以用下面的查询，得到SPID=53的信息DBCCINPUTBUFFER(53)我们可以把上述的两个查询合并起来，用下面的查询SELECTSPID=,DBName=convert(CHAR(20),ProgramName=program_name,LoginName=convert(CHAR(20),HostName=convert(CHAR(20),hostname),Status=,BlockedBy=,LoginTime=logi

9、n_time,QUERY=CAST(TEXTASVARCHA(RMAX)FROMpINNERJOINdON=INNERJOINlON=CROSSAPPLY(sql_handle)WHERE=0ANDEXISTS(SELECT1FROMMASTE.R.sysprocessesp1WHERE=这样，一次执行，就能告诉我们BLOCKINGheade的SPID信息，以及该SPID在做的语句。我们可以进一步研究该语句，以理解为什么该语句执行很慢。用这个方法有一个缺点，就是使用的时候，要求BLOCKING!存在的。如果BLOCKIN直经消失了，那么我们的方法就不管用了。方法三,长期执行一个BLOCKING

10、SCRIPT因为我们通常无法知道BLOCKIN御么时候会产生，所以通常的办法是我们长期运行一个BLOCKINGSCRIPT,这样，等下次发生的时候，我们就会有足够的信息。长期运行BLOCKINGSCRIPT性能基本上是没有影响的。因为我们每隔10秒钟抓取一次信息。缺点是，如果问题一个月才发生一次，那么，我们的BLOCKING日志信息会很大。所以这种方法适用于几天之内能重现问题。运行方法如下:如果要停止运行，我们按ctrl+c就可以了。BLOCKING：信息存在这个文件中我们可以打开这个文件,会发现SPID54被SPID53给Block住了。而随后，我们可以看到SPID=53在做什么事情:卜面是

11、BLOCKINGSCRIPT脚本，我们可以把它存为usemastergowhile1=1beginprint'Starttime:'+convert(varchar(26),getdate(),121)Print'Runningprocesses'selectspid,blocked,waittype,waittime,lastwaittype,waitresource,dbid,uid,cpu,physical_io,memusage,login_time,last_batch,open_tran,status,hostname,program_name,cm

12、d,net_library,loginamefromsysprocesses-where(kpid<>0)or(spid<51)-ChangeitifyouonlywanttoseetheworkingprocessesprintI *lockinfor*1selectconvert(smallint,req_spid)Asspidrsc_dbidAsdbid,rsc_objidAsObjId,rsc_indidAsIndId,substring,1,4)AsType,substring(rsc_text,1,16)asResourcesubstring,1,8)AsMode

13、,substring,1,5)AsStatusfromv,x,uwhere=and='LR'and=and='LS'and+1=and='L'orderbyspidprint'inputbufferforrunningprocesses'declarespidvarchar(6)>50declareibuffercursorfast_forwardforselectcast(spidasvarchar(6)asspidfromsysprocesseswherespidopenibufferfetchnextfromibuff

14、erintospidwhile(fetch_status!=-1)beginprint''print'DBCCINPUTBUFFERFORSPID'+spidexec('dbccinputbuffer('+spid+')')fetchnextfromibufferintospidenddeallocateibufferwaitfordelay'0:0:10'End这种方法的缺陷就是，会比较巨大，会占用很大的空间，如果blocking一个月甚至更长时间才发生一次，那我们的这个方法就不太适宜。方法四,我们用AgentJ

15、ob来检查BLOCKING长期运行一个BLOCKINSCRIPT勺缺点是我们每隔一段时间，去查询信息，但是大多数收集的信息是无用的。所以会导致日志文件巨大，对于一个生产系统来讲，磁盘空间满可不是个好事情，另外，有一些客户对于用命令行来长期运行TSQL脚本有所顾忌，所以我们做了一个改进。这次，我们只收集有用的信息。对于无用的信息我们不关注。这样能极大减少日志大小。我们首先创建一个观察数据库，然后建立两张表格Blocking_sysprocesses和Blocking_SQLText,建立一个存储过程和一个Job,该Job每隔一段时间去调用存储过程。只有发现有blocking的，我们才记录到表格B

16、locking_sysprocesses和Blocking_SQLText这两个表格中。如果跟blocking无关，我们就不对它进行记录。下面是TSQL®句：CREATEDATABASEMonitorBlockingGOUSEMonitorBlockingGOCREATETABLEBlocking_sysprocessesspidsmallint,kpidsmallint,blockedsmallint,waitTypebinary(2),waitTimebigInt,lastWaitTypenchar(32),waitResourcenchar(256),dbIDsmallint,

17、uidsmallint,cpuint,physical_IOint,memusageint,login_Timedatetime,last_Batchdatetime,open_Transmallintstatusnchar(30),sidbinary(86),hostNamenchar(128),program_Namenchar(128),hostProcessnchar(10),cmdnchar(16),nt_Domainnchar(128),nt_UserNamenchar(128),net_Librarynchar(12),loginNamenchar(128),context_In

18、fobinary(128),sqlHandlebinary(20),CapturedTimeStampdatetime)GOCREATETABLEdbo.Blocking_SqlText(spidsmallint,sql_textnvarchar(2000),Capture_Timestampdatetime)GOCREATEPROCEDUREdbo.checkBlockingASBEGINSETNOCOUNTON;SETTRANSACTIONISOLATIONLEVELREADUNCOMMITTEDdeclareDurationint-inmilliseconds,1000=1secdecl

19、arenowdatetimedeclareProcessesintselectDuration=100-inmilliseconds,1000=1secselectProcesses=0selectnow=getdate()CREATETABLE#Blocks_rg(spidsmallint,kpidsmallint,blockedsmallint,waitTypebinary(2),waitTimebigInt,lastWaitTypenchar(32),waitResourcenchar(256),dbIDsmallint,cpuintphysical_IOint,memusageint,

20、login_Timedatetime,last_Batchdatetime,open_Transmallint,statusnchar(30),sidbinary(86),hostNamenchar(128),program_Namenchar(128),hostProcessnchar(10),cmdnchar(16),nt_Domainnchar(128),nt_UserNamenchar(128),net_Librarynchar(12),loginNamenchar(128),context_Infobinary(128),sqlHandlebinary(20),CapturedTim

21、eStampdatetime)INSERTINTO#Blocks_rgSELECTspidkpidblocked,waitType,waitTime,lastWaitTypewaitResourcedbID,uid,cpu,physical_IOmemusage,login_Time,last_Batch,open_Tran,status,sid,hostName,program_namehostProcesscmd,nt_Domain,nt_UserNamenet_Librarycontext_Infosql_Handle,nowasCapture_Timestamp<> 0FR

22、OMmaster.sysprocesseswhereblockedANDwaitTime>DurationSETProcesses=rowcountINSERTinto#Blocks_rgSELECTsrc.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.last_Batchsrc.open_Tran,src.status,src.sid,src.ho

23、stName,gram_name,src.hostProcess,src.cmd,src.nt_Domain,src.nt_UserName,_Library,src.loginame,src.context_Info,src.sql_Handle,nowasCapture_TimestampFROMmaster.sysprocessessrcinnerjoin#Blocks_rgtrgton=src.spidifProcesses>0BEGININSERTdbo.Blocking_sysprocessesSELECT*from#Blocks_rgDECLARESQL_Handlebinary(20),SPIDsmallIntDECLAREcur_handleCURSORFORSELECTsqlHandle,spidFROM#Blocks_rg;OPENcur_HandleFETCHNEXTFROMcur_handleINTOSQL_Handle,SPIDWHILE(FETCH_STATU=S0)BEGININSERTdbo.Blocking_SqlTextSELECTSPID,CONVER(Tnvarchar(4000),tex