博客园  :: 首页  :: 新随笔  :: 联系 :: 订阅 订阅  :: 管理

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

Posted on 2011-11-25 14:55  nzperfect  阅读(2484)  评论(4编辑  收藏  举报

首先看下面这段代码,可以看出:
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/