SQLSERVER排查阻塞

1、SQL Server允許并發(fā)操作，BLOCKING是指在某一操作沒有完成之前，其他操作必須等待，以便于保證數據的完整性。BLOCKING的解決方法要查看BLOCKING的頭是什么，為什么BLOCKING頭上的語句執(zhí)行的很慢。通常來講只要我們能找到BLOCKING頭上的語句，我們總能夠想出各種各種的辦法，來提升性能，緩解或解決BLOCKING的問題。但是問題的關鍵是，我們不知道BLOCKING什么時候會發(fā)生。用戶跟我們抱怨數據庫性能很差，等我們連上數據庫去查看的時候，那時候有可能BLOCKING可能就已經過去了。性能又變好了?；蛘哂捎趩栴}的緊急性，我們直接重新啟動服務器以恢復運營。但是問題并沒有

2、最終解決，我們不知道下次問題會在什么時候發(fā)生。BLOCKING問題的后果比較嚴重。因為終端用戶能直接體驗到。他們提交一個訂單的時候，無論如何提交不上去，通常幾秒之內能完成的一個訂單提交，甚至要等待十幾分鐘，才能提交完成。更有甚者，極嚴重的BLOCKING能導致SQL Server停止工作。如下面的SQL ERRORLOG所表示, 在短短的幾分鐘之內，SPID數據從158增長到694, 并馬上導致SQL Server打了一個dump, 停止工作。我們很容易推斷出問題的原因是由于BLOCKING導致的，但是我們無法得知BLOCKING HEADER是什么，我們必須要等下次問題重現時，輔之以工具，才

3、能得知BLOCKING HEADER在做什么事情。如果信息抓取時機不對，我們可能要等問題發(fā)生好幾次，才能抓到。這時候，客戶和經理就會有抱怨了。因為我們的系統(tǒng)是生產系統(tǒng)，問題每發(fā)生一次，都會對客戶帶來損失。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-0

4、6-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.52011-06-01 16:26:50.97 Server *Dump thread - spid = 0

5、, EC = 0x00000000000000002011-06-01 16:26:50.97 Server *Stack Dump being sent to D:MSSQL10.INSTANCEMSSQLLOGSQLDump0004.txt2011-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 41242011-0

6、6-01 16:26:50.97 Server *2011-06-01 16:26:50.97 Server * Deadlocked Schedulers2011-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 Dump2011-06-01 16:26:51.01 Server Stack Signature for the dump is 0x0000000000000

7、258BLOCKING的信息抓取有很多種方法。這里羅列了幾種。并且對每種分析它的優(yōu)缺點。以便我們選擇。在枚舉方法之前，我們先簡單演示一下BLOCKING.我們首先創(chuàng)建一個測試表:DROP TABLE TESTTABLEGOCREATE TABLE dbo.TESTTABLE(ID int NULL,NAME nvarchar(50) NULL)GOINSERT INTO TESTTABLE VALUES (1, aaaa)GO然后打開一個查詢窗口，執(zhí)行下面的語句, 該語句修改一行數據，并等待3分鐘，然后在結束transactionBEGIN TRANSACTIONUPDATE TESTTABL

8、E SET NAME = bbbb WHERE ID = 1WAITFOR DELAY 00:03:00COMMIT TRANSACTION這時候，如果打開另外一個查詢窗口，執(zhí)行下面的語句，下面的語句就會被BLOCK住。UPDATE TESTTABLE SET NAME = cccc WHERE ID = 1方法一, 抓取SQL Profiler=SQL Profiler里面包含大量的信息。其中有一個事件在Errors and Warnings-Blocked Process Report專門用來獲得blocking的情況。但是因為信息量比較大，而且我們并不能很好的估算在什么時候會產生bloc

9、king，另外在生產環(huán)境使用Profiler, 對性能可能會有影響，所以SQL Profiler并不是最合適的工具。我們在這里并不對它贅述。方法二, 執(zhí)行查詢=如果我們檢查問題的時候，blocking還存在，那么，我們可以直接可以運行幾個查詢，得知BLOCKING HEADER的信息SELECT * FROM sys.sysprocesses where spid50上述查詢只是告訴我們，BLOCKING HEADER的頭是SPID=53, 但是并沒有告訴我們SPID=53在做什么事情。我們可以用下面的查詢，得到SPID=53的信息DBCC INPUTBUFFER(53)我們可以把上述的兩個查

10、詢合并起來，用下面的查詢:SELECT SPID=p.spid, DBName = convert(CHAR(20),), ProgramName = program_name, LoginName = convert(CHAR(20),), HostName = convert(CHAR(20),hostname), Status = p.status, BlockedBy = p.blocked, LoginTime = login_time, QUERY = CAST(TEXT AS VARCHAR(MAX) FROM MASTER.dbo.sysprocesse

11、s 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)這樣，一次執(zhí)行，就能告訴我們BLOCKING header的SPID信息，以及該SPID在做的語句

12、。我們可以進一步研究該語句，以理解為什么該語句執(zhí)行很慢。用這個方法有一個缺點，就是使用的時候，要求BLOCKING是存在的。如果BLOCKING已經消失了，那么我們的方法就不管用了。方法三,長期執(zhí)行一個BLOCKING SCRIPT=因為我們通常無法知道BLOCKING什么時候會產生，所以通常的辦法是我們長期運行一個BLOCKING SCRIPT, 這樣，等下次發(fā)生的時候，我們就會有足夠的信息。長期運行BLOCKING SCRIPT對性能基本上是沒有影響的。因為我們每隔10秒鐘抓取一次信息。缺點是，如果問題一個月才發(fā)生一次，那么，我們的BLOCKING日志信息會很大。所以這種方法適用于幾天之內

13、能重現問題。運行方法如下:如果要停止運行，我們按ctrl+c就可以了。BLOCKING的信息存在log.out這個文件中我們可以打開log.out這個文件, 會發(fā)現SPID 54被 SPID 53給Block住了。而隨后，我們可以看到SPID=53在做什么事情:下面是BLOCKING SCRIPT的腳本, 我們可以把它存為blocking.sqluse mastergowhile 1 =1beginprint Start time: + convert(varchar(26), getdate(), 121)Print Running processesselect spid, blocked

14、, waittype, waittime, lastwaittype, waitresource, dbid, uid, cpu, physical_io, memusage, login_time, last_batch,open_tran, status, hostname, program_name, cmd, net_library, loginamefrom sysprocesses -where (kpid 0 ) or (spid 50open ibufferfetch next from ibuffer into spidwhile (fetch_status != -1)be

15、ginprint print DBCC INPUTBUFFER FOR SPID + spidexec (dbcc inputbuffer ( + spid + )fetch next from ibuffer into spidenddeallocate ibufferwaitfor delay 0:0:10End這種方法的缺陷就是，log.out會比較巨大，會占用很大的空間，如果blocking一個月甚至更長時間才發(fā)生一次，那我們的這個方法就不太適宜。方法四,我們用Agent Job來檢查BLOCKING=長期運行一個BLOCKING SCRIPT的缺點是我們每隔一段時間，去查詢信息，但是

16、大多數收集的信息是無用的。所以會導致日志文件巨大，對于一個生產系統(tǒng)來講，磁盤空間滿可不是個好事情，另外，有一些客戶對于用命令行來長期運行TSQL腳本有所顧忌，所以我們做了一個改進。這次，我們只收集有用的信息。對于無用的信息我們不關注。這樣能極大減少日志大小。我們首先創(chuàng)建一個觀察數據庫，然后建立兩張表格 Blocking_sysprocesses和Blocking_SQLText, 建立一個存儲過程和一個Job, 該Job每隔一段時間去調用存儲過程。只有發(fā)現有blocking的，我們才記錄到表格Blocking_sysprocesses和Blocking_SQLText這兩個表格中。如果跟blo

17、cking無關，我們就不對它進行記錄。下面是TSQL語句:CREATE DATABASE MonitorBlockingGOUSE MonitorBlockingGOCREATE 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,memu

18、sage 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),sqlHandl

19、e binary(20),CapturedTimeStamp datetime)GOCREATE TABLE dbo.Blocking_SqlText(spid smallint,sql_text nvarchar(2000),Capture_Timestamp datetime ) GOCREATE PROCEDURE dbo.checkBlocking ASBEGINSET NOCOUNT ON;SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED declare Duration int - in milliseconds, 1000 = 1

20、secdeclare nowdatetimedeclare Processes intselect Duration = 100 - in milliseconds, 1000 = 1 secselect Processes = 0select now = getdate()CREATE TABLE #Blocks_rg(spid smallint,kpid smallint,blocked smallint,waitType binary(2),waitTime bigInt,lastWaitType nchar(32),waitResource nchar(256),dbID smalli

21、nt,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

22、nchar(128),context_Info binary(128),sqlHandle binary(20),CapturedTimeStamp datetime)INSERT INTO #Blocks_rgSELECT 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,

23、nt_UserName,net_Library,loginame,context_Info,sql_Handle,now as Capture_TimestampFROM master.sysprocesses where blocked 0 AND waitTime DurationSET Processes = rowcountINSERT into #Blocks_rgSELECT src.spid,src.kpid,src.blocked,src.waitType,src.waitTime,src.lastWaitType,src.waitResource,src.dbID,src.u

24、id,src.cpu,src.physical_IO,src.memusage,src.login_Time,src.last_Batch,src.open_Tran,src.status,src.sid,src.hostName,gram_name,src.hostProcess,src.cmd,src.nt_Domain,src.nt_UserName,_Library,src.loginame,src.context_Info,src.sql_Handle,now as Capture_TimestampFROM master.sysprocesses src

25、 inner join #Blocks_rg trgt on trgt.blocked = src.spidif Processes 0BEGININSERT dbo.Blocking_sysprocesses SELECT * from #Blocks_rgDECLARE SQL_Handle binary(20), SPID smallInt;DECLARE cur_handle CURSOR FOR SELECT sqlHandle, spid FROM #Blocks_rg;OPEN cur_HandleFETCH NEXT FROM cur_handle INTO SQL_Handle, SPIDWHILE (FETCH_STATUS = 0)BEGININSERT