转载自:

 

SQL Server 2008中包含一个新功能,旨在帮助解决特别棘手的连接问题。这个新功能是Connectivity Ring Buffer,它可以捕捉每一个由服务器发起的连接关闭记录(server-initiated connection closure),包括每一个session或登录失败事件。为了进行有效的故障排除,Ring Buffer会尝试提供客户端的故障和服务器的关闭动作之间的关系信息。只要服务器在线, 最高1K的Ring Buffer就会被保存,1000条记录后,Buffer开始循环覆盖,即从最老的记录开始覆盖。Connectivity Ring Buffer的记录是能够使用DMV查询的:

 

1
2
SELECT 
CAST
(record 
AS 
XML) 
FROM 
sys.dm_os_ring_buffers   
WHERE 
ring_buffer_type = 
'RING_BUFFER_CONNECTIVITY'

 

上述指令会选择所有记录为XML类型;在Management Studio中,你可以单击记录,从而获得更具可读性的版本。如果你想使用SQL查询XML记录从而找到相应的问题,你可以使用SQL server的XML 支持,将之变为一个临时的表,从而查询记录。

 

一个基本的Buffer entry:Killed SPID

 

一个导致服务器发起的连接关闭的简单方法是打开两个SQL服务器的连接,找到一个连接的SPID,然后从另一个连接中将该SPID杀死。

 

C:\>osql -E   

1> SELECT @@spid    
2> go    
------    
51    
(1 row affected)

C:\>osql -E   

1> kill 51    
2> go    
1>

如果你做了上述工作,然后查询Ring Buffer,你会得到和如下类似的结果:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
<
Record 
id
=
"2" 
type
=
"RING_BUFFER_CONNECTIVITY" 
time
=
"110448275"
>
<
ConnectivityTraceRecord
>
<
RecordType
>ConnectionClose</
RecordType
>
<
RecordSource
>Tds</
RecordSource
>
<
Spid
>55</
Spid
>
<
SniConnectionId
>B7882F3C-3BA9-45A7-8D23-3C5C05F9BDF9</
SniConnectionId
>
<
SniProvider
>4</
SniProvider
>
<
RemoteHost
><
local 
machine></
RemoteHost
>
<
RemotePort
>0</
RemotePort
>
<
LocalHost 
/>
<
LocalPort
>0</
LocalPort
>
<
RecordTime
>5/6/2008 22:47:35.880</
RecordTime
>
<
TdsBuffersInformation
>
<
TdsInputBufferError
>0</
TdsInputBufferError
>
<
TdsOutputBufferError
>0</
TdsOutputBufferError
>
<
TdsInputBufferBytes
>60</
TdsInputBufferBytes
>
</
TdsBuffersInformation
>
<
TdsDisconnectFlags
>
<
PhysicalConnectionIsKilled
>0</
PhysicalConnectionIsKilled
>
<
DisconnectDueToReadError
>0</
DisconnectDueToReadError
>
<
NetworkErrorFoundInInputStream
>0</
NetworkErrorFoundInInputStream
>
<
ErrorFoundBeforeLogin
>0</
ErrorFoundBeforeLogin
>
<
SessionIsKilled
>1</
SessionIsKilled
>
<
NormalDisconnect
>0</
NormalDisconnect
>
<
NormalLogout
>0</
NormalLogout
>
</
TdsDisconnectFlags
>
</
ConnectivityTraceRecord
>
<
Stack
>
<
frame 
id
=
"0"
>0X01CA0B00</
frame
>
<
frame 
id
=
"1"
>0X01CA0DB1</
frame
>
<
frame 
id
=
"2"
>0X01DF6162</
frame
>
<
frame 
id
=
"3"
>0X02E53C98</
frame
>
<
frame 
id
=
"4"
>0X02E54845</
frame
>
<
frame 
id
=
"5"
>0X02E57BE9</
frame
>
<
frame 
id
=
"6"
>0X02E38F57</
frame
>
<
frame 
id
=
"7"
>0X02E3B2C0</
frame
>
<
frame 
id
=
"8"
>0X02E3C832</
frame
>
<
frame 
id
=
"9"
>0X02E3D55E</
frame
>
<
frame 
id
=
"10"
>0X781329BB</
frame
>
<
frame 
id
=
"11"
>0X78132A47</
frame
>
</
Stack
>
</
Record
>

 

不同的记录类型包括不同的信息。Connectivity Ring Buffer 记录的三种记录类型分别是:ConnectionClose,Error,和LoginTimers。上面的结果是一个ConnectionClose,因为这不是一个登陆时超时,或者其它的登陆失败的场景:

 

1
<
RecordType
>ConnectionClose</
RecordType
>

 

我们可以看出,SPID 55的连接关闭了:

1
2
<![endif]>
<
Spid
>55</
Spid
>

 

我们可以看到连接是本地的(<local machine>表明其是一个本地的,shared memory类型的连接)。

1
2
<![endif]>
<
RemoteHost
><
local 
machine></
RemoteHost
>

 

当使用TCP协议进行连接时,可以获得更多的相关信息-例如,本地IP地址,端口,以及远程IP地址和端口,从而允许你唯一的确定客户机及其应用。另外,Ring Buffer包括了一个时间戳以及与之相对应的SPID(如果有的话),这样才能形成一个完整的对应关系。(因为随着时间的推移SPID会被不同的连接所重用)。

 

我们同样可以看到客户发的TDS包中有多少bytes,并且可以知道是否在TDS中有任何的错误:

1
2
3
<
TdsInputBufferError
>0</
TdsInputBufferError
>   
<
TdsOutputBufferError
>0</
TdsOutputBufferError
>    
<
TdsInputBufferBytes
>60</
TdsInputBufferBytes
>

 

最相关的,最易于分析的信息记录在TdsDisconnectFlags中,有一系列的值,记录了关闭连接的状态。这里,我们看到没有发现错误,但是这里记录了这也不是一个正常的断开或者一个正常的登出。从如下的flag中,这个session是被杀死的:

 

1
<
SessionIsKilled
>1</
SessionIsKilled
>

 

一个更有意思的例子:DC 连接性问题

 

跟踪被杀死的SPID看起来很cool。但是Connectivity Ring Buffer更重要的最用是帮助我们可以在不使用network monitor的情况下来解决棘手的问题。以下是一个Connectivity Ring Buffer中Login Time记录的例子,如果没有代价高昂的问题重现过程并且分析网络抓获的包,这个问题很难查明:

 

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
<
Record 
id
=
"3" 
type
=
"RING_BUFFER_CONNECTIVITY" 
time
=
"112254962"
>
<
ConnectivityTraceRecord
>
<
RecordType
>LoginTimers</
RecordType
>
<
Spid
>0</
Spid
>
<
SniConnectionId
>B401B045-3C82-4AAC-A459-DB0520925431</
SniConnectionId
>
<
SniConsumerError
>17830</
SniConsumerError
>
<
SniProvider
>4</
SniProvider
>
<
State
>102</
State
>
<
RemoteHost
><
local 
machine></
RemoteHost
>
<
RemotePort
>0</
RemotePort
>
<
LocalHost 
/>
<
LocalPort
>0</
LocalPort
>
<
RecordTime
>5/6/2008 23:17:42.556</
RecordTime
>
<
TdsBuffersInformation
>
<
TdsInputBufferError
>0</
TdsInputBufferError
>
<
TdsOutputBufferError
>232</
TdsOutputBufferError
>
<
TdsInputBufferBytes
>198</
TdsInputBufferBytes
>
</
TdsBuffersInformation
>
<
LoginTimers
>
<
TotalLoginTimeInMilliseconds
>21837</
TotalLoginTimeInMilliseconds
>
<
LoginTaskEnqueuedInMilliseconds
>0</
LoginTaskEnqueuedInMilliseconds
>
<
NetworkWritesInMilliseconds
>2</
NetworkWritesInMilliseconds
>
<
NetworkReadsInMilliseconds
>77</
NetworkReadsInMilliseconds
>
<
SslProcessingInMilliseconds
>3</
SslProcessingInMilliseconds
>
<
SspiProcessingInMilliseconds
>21756</
SspiProcessingInMilliseconds
>
<
LoginTriggerAndResourceGovernorProcessingInMilliseconds
>0</
LoginTriggerAndResourceGovernorProcessingInMilliseconds
>
</
LoginTimers
>
</
ConnectivityTraceRecord
>
<
Stack
>
<
frame 
id
=
"0"
>0X01CA0B00</
frame
>
<
frame 
id
=
"15"
>0X02E3C832</
frame
>
</
Stack
>
</
Record
>

 

在这个情况下,在客户端,我们可以看到:   

[SQL Server Native Client 10.0]Shared Memory Provider: Timeout error [258].    
[SQL Server Native Client 10.0]Login timeout expired    
[SQL Server Native Client 10.0]Unable to complete login process due to delay in login response

 

获得操作系统的错误消息,不能说明任何问题:

C:\>net helpmsg 258   

The wait operation timed out.

 

在服务器的errorlogs里面,什么都没有。然而Ring Buffer中的记录非常有意思。LoginTimers中记录了整体处理时间(overall processing time):

 

1
<
TotalLoginTimeInMilliseconds
>21837</
TotalLoginTimeInMilliseconds
>

 

在整个登陆过程中,根据不同阶段所做的工作的不同,TotalLoginTimeInMilliseconds被分解为一个个子项(由于取整的操作,这些数字最终加起来不会等于总体的时间。在上面所举的例子中他们相差1)。在这种情况下,SspiProcessingInMilliseconds 看起来很有趣,它用了近22秒: 

  

1
2
<![endif]>
<
SspiProcessingInMilliseconds
>21756</
SspiProcessingInMilliseconds
>

 

SSPI(Security Support Provider Interface),是一个SQL Server使用Windows Authentication的接口。当Windows login是一个domain account,SQL Server使用SSPI和Domain Controller交互,从而验证用户身份。记录中可以看到,SSPI过程占用了大量的时间,这表明和Domain Controller交互时有延时,很有可能是SQL服务器和DC之间的物理连接有问题,或者DC上的一些软件问题。可以看到,我们没有进行网络抓包,也没有重现问题,我们就已经把问题缩小到SQL Server和Domain Controller之间的交互上面来了。(Connectivity Ring Buffer默认是打开的)

 

Trace Flags

Connectivity Ring Buffer 默认是打开的,它默认跟踪所有的由服务器发起的连接关闭。如果你在客户端看到一个错误,但是在Ring Buffer中没有记录,这就表明服务器看到的是一种“重置”类型的连接关闭,这种连接关闭类似于客户端正常关闭连接的行为,或者是由于服务器外部因素所造成的连接关闭;(例如,一个网络硬件的故障)。如果是这种情况,你就需要关注潜在的网络互联问题。如果你在Ring Buffer中看到了一个条目它可以指出为什么服务器要关闭这个链接,那么这个条目就很可能可以极大的帮助我们进行故障排查。例如,如果你看到一个连接关闭是由于TDS包中的信息不合法,那么你就可以去检查那些可能会损坏网络包的设备,包括网卡,路由和集线器等。下面你会看到,通过使用一个trace flag,你可以让Connectivity Ring Buffer记录所有连接关闭事件。这样你就能观察到客户端发起的连接关闭的情形和潜在的错误。

 

有两个trace flag,可以用于改变Connectivity Ring Buffer 的行为。

完全关闭Connectivity Ring Buffer,可以开启trace flag 7826:

DBCC TRACEON (7826, -1)

 

默认情况下客户端发起的连接关闭是不被记录的(因为这是正常的情况,而不是一个错误);当一个客户结束的它的session,它就断开。一般来说,我们建议不要去跟踪客户端发起的连接关闭,因为真正有用的Buffer记录会被覆盖(当你有很多正常表现的连接时,这种情况发生可能性会很大),或者会被隐藏在一个堆正常情况的记录中。这会使你错过真正的错误问题。如果你真的想要观察客户端的连接关闭,你可以使用trace flag 7827来开启这个功能:

DBCC TRACEON (7827, -1)

 

<Frame>tags是什么?

通过sys.dm_os_ring_buffers DMV 可以访问一系列内部信息,它包含了但不仅限于Connectivity Ring Buffer。作为DMV基础的一部分,大多数的Ring Buffers 提供了事件发生时的栈踪迹(stack trace),每一个<frame>提供了一个十六进制的函数地址。这些都可以分解为函数名,并dump Sqlservr.exe进程,在WinDbg打开dump,并采用基于函数的地址的LM命令。

以下是一个常用的示例脚本:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
--   
--    
--RING BUFFER CONNECTIVITY    
--    
 
select    
   
record    
  
,
CAST
(record 
AS 
XML)    
  
,
CAST
(record 
as 
XML).value(
'/Record[1]/ConnectivityTraceRecord[1]/SniConsumerError[1]'
'int'
as 
SniConsumerErrorValue    
  
,
CAST
(record 
as 
XML).value(
'/Record[1]/ConnectivityTraceRecord[1]/RemoteHost[1]'
'varchar(20)'
as 
RemoteHost    
   
from 
sys.dm_os_ring_buffers    
 
where    
  
ring_buffer_type = 
'RING_BUFFER_CONNECTIVITY'    
  
/*    
   
and    
     
record   
like 
'%<RecordTime>2/22/2011%'    
     
record   
like 
'%<SniConsumerError>17830</SniConsumerError>%'    
     
record   
like 
'%<SniConsumerError>18456</SniConsumerError>%'    
     
record   
like 
'%<SniConsumerError>4014</SniConsumerError>%'    
     
record   
like 
'%<SniConsumerError>17810</SniConsumerError>%'    
  
*/

本文转自UltraSQL51CTO博客,原文链接: http://blog.51cto.com/ultrasql/1583402,如需转载请自行联系原作者