出自: http://blogs.msdn.com/b/apgcdsd/archive/2011/11/21/ring-buffer-sql-server-2008.aspx
SQL Server 2008 中包含一个新功能,旨在帮助解决特别棘手的连接问题。这个新功能是 Connectivity Ring Buffer ,它可以捕捉每一个由服务器发起的连接关闭记录 (server-initiated connection closure) ,包括每一个 session 或登录失败事件。为了进行有效的故障排除, Ring Buffer 会尝试提供客户端的故障和服务器的关闭动作之间的关系信息。只要服务器在线 , 最高 1K 的 Ring Buffer 就会被保存, 1000 条记录后, Buffer 开始循环覆盖,即从最老的记录开始覆盖。 Connectivity Ring Buffer 的记录是能够使用 DMV 查询的:
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
,你会得到和如下类似的结果:
< 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 ,因为这不是一个登陆时超时,或者其它的登陆失败的场景:
<
RecordType
>
ConnectionClose
</
RecordType
>
我们可以看出,
SPID 55
的连接关闭了:
<![endif]>
< Spid > 55 </ Spid >
我们可以看到连接是本地的(
<local machine>
表明其是一个本地的,
shared memory
类型的连接)。
<![endif]>
< RemoteHost > < local machine > ; </ RemoteHost >
当使用 TCP 协议进行连接时,可以获得更多的相关信息 - 例如,本地 IP 地址,端口,以及远程 IP 地址和端口,从而允许你唯一的确定客户机及其应用。另外, Ring Buffer 包括了一个时间戳以及与之相对应的 SPID (如果有的话),这样才能形成一个完整的对应关系。(因为随着时间的推移 SPID 会被不同的连接所重用)。
我们同样可以看到客户发的 TDS 包中有多少 bytes ,并且可以知道是否在 TDS 中有任何的错误:
<
TdsInputBufferError
>
0
</
TdsInputBufferError
>
<
TdsOutputBufferError
>
0
</
TdsOutputBufferError
>
<
TdsInputBufferBytes
>
60
</
TdsInputBufferBytes
>
最相关的,最易于分析的信息记录在 TdsDisconnectFlags 中,有一系列的值,记录了关闭连接的状态。这里,我们看到没有发现错误,但是这里记录了这也不是一个正常的断开或者一个正常的登出。从如下的 flag 中,这个 session 是被杀死的:
<
SessionIsKilled
>
1
</
SessionIsKilled
>
一个更有意思的例子:DC 连接性问题
跟踪被杀死的 SPID 看起来很 cool 。但是 Connectivity Ring Buffer 更重要的最用 是帮助我们可以在不使用 network monitor 的情况下来解决棘手的问题。以下是一个 Connectivity Ring Buffer 中 Login Time 记录的例子,如果没有代价高昂的问题重现过程并且分析网络抓获的包,这个问题很难查明:
< 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 ):
<
TotalLoginTimeInMilliseconds
>
21837
</
TotalLoginTimeInMilliseconds
>
在整个登陆过程中,根据不同阶段所做的工作的不同,
TotalLoginTimeInMilliseconds
被分解为一个个子项(由于取整的操作,这些数字最终加起来不会等于总体的时间。在上面所举的例子中他们相差
1
)。在这种情况下,
SspiProcessingInMilliseconds
看起来很有趣,它用了近
22
秒:
<![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 命令。