关于Blocked Process Report 一个让人迷惑的问题分析

首先看下面这段代码，可以看出：
blocked-process是被阻塞的进程，执行的sql是select * from temp1
blocking-process是正在产生阻塞的进程，执行的sql是select * from temp1 with(nolock)
如果你偶尔抓到了这样的report，肯定会奇怪吧，为什么呢？理论下面的sql不会对上面的sql产生阻塞。

<blocked-process-report>
  <blocked-process>
    <process id="process3d92550" taskpriority="0" logused="0" waitresource="RID: 2:1:218:0" waittime="16975" ownerId="3047491" transactionname="SELECT" lasttranstarted="2011-11-25T14:24:52.210" XDES="0x78ae138" lockMode="S" schedulerid="4" kpid="4676" status="suspended" spid="69" sbid="0" ecid="0" priority="0" trancount="0" lastbatchstarted="2011-11-25T14:24:52.210" lastbatchcompleted="2011-11-25T14:12:08.507" clientapp="Microsoft SQL Server Management Studio - 查询" hostname="R192249" hostpid="9808" loginname="my\name" isolationlevel="read committed (2)" xactid="3047491" currentdb="2" lockTimeout="4294967295" clientoption1="671090784" clientoption2="390200">
      <executionStack>
        <frame line="1" sqlhandle="0x0200000088baad31046d031f04c8e7293882ce42521d893f"/>
      </executionStack>
      <inputbuf>
select * from temp1   </inputbuf>
    </process>
  </blocked-process>
  <blocking-process>
    <process status="sleeping" spid="68" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2011-11-25T14:25:00.617" lastbatchcompleted="2011-11-25T14:25:00.617" clientapp="Microsoft SQL Server Management Studio - 查询" hostname="R192249" hostpid="9808" loginname="my\name" isolationlevel="read committed (2)" xactid="3047423" currentdb="2" lockTimeout="4294967295" clientoption1="671090784" clientoption2="390200">
      <executionStack />
      <inputbuf>

select * from temp1 with(nolock)   </inputbuf>
    </process>
  </blocking-process>
</blocked-process-report>

下面将重现这个阻塞：
1.首先要设置blocked process shreshold为5秒，这样就可以trace到它：

sp_configure 'show advanced options',1 ; 
GO 
RECONFIGURE; 
GO 
sp_configure 'blocked process threshold',5 ; 
GO 
RECONFIGURE; 
GO

2.创建一个trace，来抓取block:

-- Create a Queue
declare @rc int
declare @TraceID int
declare @maxfilesize bigint
set @maxfilesize = 50 
exec @rc = sp_trace_create @TraceID output, 2, N'D:\Tmp\1', @maxfilesize, NULL 
if (@rc != 0) goto error
-- Client side File and Table cannot be scripted
-- Set the events
declare @on bit
set @on = 1
exec sp_trace_setevent @TraceID, 137, 15, @on
exec sp_trace_setevent @TraceID, 137, 1, @on
exec sp_trace_setevent @TraceID, 137, 13, @on

-- Set the Filters
declare @intfilter int
declare @bigintfilter bigint
-- Set the trace status to start
exec sp_trace_setstatus @TraceID, 1
-- display trace id for future references
select TraceID=@TraceID
goto finish
error: 
select ErrorCode=@rc
finish: 
go

3.创建测试表并插入数据：

use tempdb
create table temp1
(rowid int)
insert into temp1 values (1)
go

4.新建两个会话查询，在会话一中执行：

begin tran
update temp1
set rowid = rowid + 1
--select * from temp1 with(nolock)
--rollback

5.在会话二中执行：

select * from temp1

6.然后再去会话一中执行

select * from temp1 with(nolock)

7.此时会发现，会话二中的sql一直处在等待状态，稍等十几秒后，去会话一执行rollback，这样会话二方可查询出结果。

8.然后执行下面的sql，查看blocked process report:

select cast(TextData as xml), SPID, EndTime, Duration/1000/1000
from fn_trace_gettable(N'D:\Tmp\1.trc', default)
where eventclass = 137

此时就会出现本文最上面的blocked process report，让人误以为是select * from temp1 with(nolock)阻塞了select * from temp1.

9.删除测试数据并停止trace：

drop table temp1
--stop the trace
exec sp_trace_setstatus 2, 0
--delete the trace but leaves the file on the drive
exec sp_trace_setstatus 2, 2

10.总结这个问题，是由于处于同一个事务内的两个sql分两次执行，造成了blocked process report只记录最后一个sql，这样就会另人产生误解，找到不问题所在，应该是需要注意的一个地方。

本文代码参考：http://www.sqlservercentral.com/articles/Blocking/64474/