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

buhong

出自：http://blogs.msdn.com/b/apgcdsd/archive/2011/11/21/ring-buffer-sql-server-2008.aspx
SQL Server 2008中包含一个新功能，旨在帮助解决特别棘手的连接问题。这个新功能是Connectivity Ring Buffer，它可以捕捉每一个由服务器发起的连接关闭记录(server-initiatedconnection closure)，包括每一个session或登录失败事件。为了进行有效的故障排除，Ring Buffer会尝试提供客户端的故障和服务器的关闭动作之间的关系信息。只要服务器在线,最高1K的RingBuffer就会被保存，1000条记录后，Buffer开始循环覆盖，即从最老的记录开始覆盖。ConnectivityRing Buffer的记录是能够使用DMV查询的：
　　
　　SELECTCAST(recordASXML)FROMsys.dm_os_ring_buffers
WHEREring_buffer_type='RING_BUFFER_CONNECTIVITY'
　　
　　上述指令会选择所有记录为XML类型;在Management Studio中,你可以单击记录,从而获得更具可读性的版本。如果你想使用SQL查询XML记录从而找到相应的问题,你可以使用SQLserver的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，你会得到和如下类似的结果：
　　<Recordid="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;localmachine&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>
　　<frameid="0">0X01CA0B00</frame>
　　<frameid="1">0X01CA0DB1</frame>
　　<frameid="2">0X01DF6162</frame>
　　<frameid="3">0X02E53C98</frame>
　　<frameid="4">0X02E54845</frame>
　　<frameid="5">0X02E57BE9</frame>
　　<frameid="6">0X02E38F57</frame>
　　<frameid="7">0X02E3B2C0</frame>
　　<frameid="8">0X02E3C832</frame>
　　<frameid="9">0X02E3D55E</frame>
　　<frameid="10">0X781329BB</frame>
　　<frameid="11">0X78132A47</frame>
　　</Stack>
　　</Record>
　　不同的记录类型包括不同的信息。Connectivity Ring Buffer记录的三种记录类型分别是：ConnectionClose，Error，和LoginTimers。上面的结果是一个ConnectionClose，因为这不是一个登陆时超时，或者其它的登陆失败的场景：
　　
<RecordType>ConnectionClose</RecordType>
　　我们可以看出，SPID55的连接关闭了：

<![endif]>
　　<Spid>55</Spid>
　　我们可以看到连接是本地的（<local machine>表明其是一个本地的，shared memory类型的连接）。

<![endif]>
　　<RemoteHost>&lt;localmachine&gt;</RemoteHost>
　　
　　当使用TCP协议进行连接时，可以获得更多的相关信息-例如，本地IP地址，端口，以及远程IP地址和端口，从而允许你唯一的确定客户机及其应用。另外，RingBuffer包括了一个时间戳以及与之相对应的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更重要的最用是帮助我们可以在不使用networkmonitor的情况下来解决棘手的问题。以下是一个Connectivity Ring Buffer中Login Time记录的例子，如果没有代价高昂的问题重现过程并且分析网络抓获的包，这个问题很难查明：
　　<Recordid="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;localmachine&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>
　　<frameid="0">0X01CA0B00</frame>
　　…
　　<frameid="15">0X02E3C832</frame>
　　</Stack>
　　</Record>
　　在这个情况下，在客户端，我们可以看到：
[SQL Server Native Client 10.0]Shared Memory Provider: Timeout error [258].
[SQL Server Native Client 10.0]Login timeoutexpired
[SQL Server Native Client 10.0]Unable to complete login process due to delay in login response
　　获得操作系统的错误消息，不能说明任何问题：
　　
C:\>nethelpmsg258
Thewait operation timed out.
　　在服务器的errorlogs里面，什么都没有。然而Ring Buffer中的记录非常有意思。LoginTimers中记录了整体处理时间（overallprocessing time）：
　　
<TotalLoginTimeInMilliseconds>21837</TotalLoginTimeInMilliseconds>
　　在整个登陆过程中，根据不同阶段所做的工作的不同，TotalLoginTimeInMilliseconds被分解为一个个子项（由于取整的操作，这些数字最终加起来不会等于总体的时间。在上面所举的例子中他们相差1）。在这种情况下，SspiProcessingInMilliseconds看起来很有趣，它用了近22秒：

<![endif]>
　　<SspiProcessingInMilliseconds>21756</SspiProcessingInMilliseconds>
　　SSPI（Security Support Provider Interface），是一个SQL Server使用WindowsAuthentication的接口。当Windows login是一个domain account，SQL Server使用SSPI和DomainController交互，从而验证用户身份。记录中可以看到，SSPI过程占用了大量的时间，这表明和Domain Controller交互时有延时，很有可能是SQL服务器和DC之间的物理连接有问题，或者DC上的一些软件问题。可以看到，我们没有进行网络抓包，也没有重现问题，我们就已经把问题缩小到SQLServer和Domain Controller之间的交互上面来了。（Connectivity Ring Buffer默认是打开的）
Trace Flags
　　Connectivity Ring Buffer默认是打开的，它默认跟踪所有的由服务器发起的连接关闭。如果你在客户端看到一个错误，但是在Ring Buffer中没有记录，这就表明服务器看到的是一种“重置”类型的连接关闭，这种连接关闭类似于客户端正常关闭连接的行为，或者是由于服务器外部因素所造成的连接关闭；（例如，一个网络硬件的故障）。如果是这种情况，你就需要关注潜在的网络互联问题。如果你在RingBuffer中看到了一个条目它可以指出为什么服务器要关闭这个链接，那么这个条目就很可能可以极大的帮助我们进行故障排查。例如，如果你看到一个连接关闭是由于TDS包中的信息不合法，那么你就可以去检查那些可能会损坏网络包的设备，包括网卡，路由和集线器等。下面你会看到，通过使用一个traceflag，你可以让Connectivity Ring Buffer记录所有连接关闭事件。这样你就能观察到客户端发起的连接关闭的情形和潜在的错误。
　　有两个trace flag，可以用于改变Connectivity Ring Buffer的行为。
　　完全关闭Connectivity Ring Buffer，可以开启trace flag 7826：
　　DBCCTRACEON(7826,-1)
　　默认情况下客户端发起的连接关闭是不被记录的（因为这是正常的情况，而不是一个错误）；当一个客户结束的它的session，它就断开。一般来说，我们建议不要去跟踪客户端发起的连接关闭，因为真正有用的Buffer记录会被覆盖（当你有很多正常表现的连接时，这种情况发生可能性会很大），或者会被隐藏在一个堆正常情况的记录中。这会使你错过真正的错误问题。如果你真的想要观察客户端的连接关闭，你可以使用traceflag 7827来开启这个功能：
　　DBCCTRACEON(7827,-1)
<Frame>tags是什么？
　　通过sys.dm_os_ring_buffersDMV可以访问一系列内部信息，它包含了但不仅限于Connectivity Ring Buffer。作为DMV基础的一部分，大多数的RingBuffers提供了事件发生时的栈踪迹（stack trace），每一个<frame>提供了一个十六进制的函数地址。这些都可以分解为函数名，并dumpSqlservr.exe进程，在WinDbg打开dump，并采用基于函数的地址的LM命令。