利用Ring Buffer在SQL Server 2008中进行连接故

系统 3327 0
原文: 利用Ring Buffer在SQL Server 2008中进行连接故障排除

出自: 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 > &lt; local  machine &gt ; </ 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 > &lt; local  machine &gt ; </ 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 > &lt; local  machine &gt ; </ 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 命令。

利用Ring Buffer在SQL Server 2008中进行连接故障排除


更多文章、技术交流、商务合作、联系博主

微信扫码或搜索:z360901061

微信扫一扫加我为好友

QQ号联系: 360901061

您的支持是博主写作最大的动力,如果您喜欢我的文章,感觉我的文章对您有帮助,请用微信扫描下面二维码支持博主2元、5元、10元、20元等您想捐的金额吧,狠狠点击下面给点支持吧,站长非常感激您!手机微信长按不能支付解决办法:请将微信支付二维码保存到相册,切换到微信,然后点击微信右上角扫一扫功能,选择支付二维码完成支付。

【本文对您有帮助就好】

您的支持是博主写作最大的动力,如果您喜欢我的文章,感觉我的文章对您有帮助,请用微信扫描上面二维码支持博主2元、5元、10元、自定义金额等您想捐的金额吧,站长会非常 感谢您的哦!!!

发表我的评论
最新评论 总共0条评论