使用network monitor trace发现应用程序在数据库上执行时的timeout错误

  • Article

一个奇怪的timeout 问题 —-- 使用network monitor trace发现应用程序在数据库上执行时的timeout错误。

问题的描述：

客户使用一个应用程序向数据库中装载数据。该程序执行大量的insert和bulk insert的命令。

客户的使用过程中，每4次执行就有一次会报timeout的错误。当timeout错误报出的时候，该程序执行了不到1分钟。

 

问题的检查：

既然错误信息已经明确的指出了是timeout，那我们首先需要检查客户端应用程序相关的timeout设置。

通常跟数据库有关的两个timeout设置分别为：连接timeout和语句timeout。

连接timeout是指客户端程序创建数据库连接时，多少时间没有响应，就报出timeout的错误。

语句timeout是指当客户端发送语句给SQL Server执行时，如果SQL Server多次时间没有返回结果集，就报timeout的错误。

以上两个timeout 都是在客户端连接的属性中设置，SQL Server没有相关的设置选项。

除了以上两个timeout设置，SQL Server 还有另外一个timeout的设置：lock_timeout. 这个timeout的定义是，当客户端连接开始执行语句并且出现等待lock资源的时候，

如果在设置的时间内一直没有获得lock 资源，就报出timeout的错误并cancel当前的连接。这个设置也是基于连接的，客户端程序在创建连接后，可以在当前连接中通过执行以下语句来设置：

SET LOCK_TIMEOUT timeout_period

 

根据以上对于timeout设置的介绍，我们检查了应用程序的connection timeout和statememt timeout的设置。这里的connection timeout设置为20分钟，而statement timeout设置为150 秒。从这两个设置来看，目前的timeout跟connection和statement都是没有关系的。

 

 

更多信息的收集：

在这里，我们分别在应用程序服务器和数据库服务器同时开启的network trace的收集，然后重现问题，停止network trace收集。

Network monitor 工具是我们在处理SQL Server连接错误时经常使用的一个工具， 最新的3.4的版本可以从这里下载：

https://www.microsoft.com/downloads/details.aspx?FamilyID=983b941d-06cb-4658-b7f6-3088333d062f&displaylang=en

 

收集下来的trace依然使用network monitor工具打开，这个工具自带了SQL Server TDS包的parse，如果在该网络环境中没有加密的协议使用，这个parse可以将TDS包解密成明文的SQL语句。也就是说，我们可以从network trace的TDS包中直接看到传递的语句。

在这个netmon中，timeout的错误是发生在Frame 420247中的。

Frame 418164是client app发送了一个RPC call 给SQL Server。SQL Server 在frame 418222 立刻确认了这个包，通知client已经收到了这个RCPrequest。17秒以后，SQL Server结束了这个语句，然后在frame 419519中回复了TDS:response包返回结果集。在这个RPC call的语句之后，client APP 在frame 419520发了一个TDS:TransMgrReq的包，这个包也立刻被SQL Server在frame 419537确认了，14秒之后，client就直接发出了timeout的包，然后终止了这个连接。

看起来的问题是和这个TDS:TansMgrReq的包有关系的。那么TansMgrReq是什么意思呢？为什么会出现TansMgrReq的包呢？我们在[MS-TDS]: Tabular Data Stream Protocol Specification (https://msdn.microsoft.com/en-us/library/dd304523(v=PROT.13).aspx)的文章中找到的对TansMgrReq包的解释：

Stream Name:

 TransMgrReq

Stream Function:

Query and control operations pertaining to the lifecycle and state of local and distributed transaction objects. Note that distributed transaction operations are coordinated through a Distributed Transaction Coordinator (DTC) implemented to the DTC Interface Specification.

RequestType

The types of transaction manager operations desired by the client are specified as follows. If an unknown Type is specified, the message receiver SHOULD disconnect the connection.

· 0 = TM_GET_DTC_ADDRESS. Returns DTC network address as result set with a single-column, single-row binary value.

· 1 = TM_PROPAGATE_XACT. Imports DTC transaction into the server and returns a local transaction descriptor as a varbinary result set.

· 5 = TM_BEGIN_XACT. Begins a transaction and returns the descriptor in an ENVCHANGE type 8.

· 6 = TM_PROMOTE_XACT. Converts an active local transaction into a distributed transaction and returns an opaque buffer in an ENVCHANGE type 15.

· 7 = TM_COMMIT_XACT. Commits a transaction. Depending on the payload of the request, it can additionally request that another local transaction be started.

· 8 = TM_ROLLBACK_XACT. Rolls back a transaction. Depending on the payload of the request it can indicate that after the rollback, a local transaction is to be started.

· 9 = TM_SAVE_XACT. Sets a savepoint within the active transaction. This request MUST specify a nonempty name for the savepoint

从这段描述中，我们了解到，TansMgrReq包是MSDTC 使用的。Client APP在open和commit transaction的时候，我们都会看到TansMgrReq包存在、

接下来我们详细检查frame 419520的包：

0.0000000 4100# 7:00:36 PM 10/28/2011 866.5000000 CSSOPaymentMakerService.exe 10.23.94.66 10.23.88.36 TDS TDS:TransMgrReq, Version = 7.2 (0x72090002), SPID = 0, PacketID = 1, Flags=...AP..., SrcPort=2063, DstPort=1803, PayloadLen=34, Seq=3113173592 - 3113173626, Ack=2166327246, Win=65060 {TDS:3, TCP:2, IPv4:1}

  - TDSTransMgrReqData:

   + TDSAllHeadersData: Head Type = MARS Header

     RequestType: 7 (0x7) --7= TM_COMMIT_XACT. Commits a transaction. Depending on the payload of the request, it can additionally request that another local transaction be started

   + TM_COMMIT_XACT: --这里的包是要求transaction commit

因此我们在追溯这个trace中的上一个TansMgrReq包

0.0000000 4095 7:00:18 PM 10/28/2011 849.1718750 CSSOPaymentMakerService.exe 10.23.94.66 10.23.88.36 TDS TDS:TransMgrReq, Version = 7.2 (0x72090002), SPID = 0, PacketID = 1, Flags=...AP..., SrcPort=2063, DstPort=1803, PayloadLen=34, Seq=3113172574 - 3113172608, Ack=2166327134, Win=65172 {TDS:3, TCP:2, IPv4:1}

  - TDSTransMgrReqData:

   + TDSAllHeadersData: Head Type = MARS Header

·      RequestType: 5 (0x5) --5 = TM_BEGIN_XACT. Begins a transaction and returns the descriptor in an ENVCHANGE type 8.

   + TM_BEGIN_XACT: --这个事务是在这里开始的

现在我们就得到了整个DTC的过程，7:00:18开始了DTC，然后执行了一些RPC call,在7:00:36 client app要求事务提交，在7:00:51的时候client还没有收到SQL Server 关于transaction commit的确认，然后直接报出了timeout 错误并rollback整个 transaction.整个transaction的生存期为33秒。

接下来的问题是，为什么transaction的生存期是33秒？如果我们能够延长这个transaction的生存期，这个问题是不是就不会再发生了？

在DTC component的设置中，有一个选项是用来控制DTC transaction的生存期的，默认值是60秒(open Control Panel - > Administrative Tools -> Component Services)。

一旦活动的DTC transaction超过了这里设置的时间还没有结束，Transaction manager就会直接关闭这个transaction并且报出timeout的错误。这个timeout的设置只有在使用DTC transaction的时候才生效。

到这里，我们已经找到了问题的最终原因。在延长这个transaction timeout到180秒之后，应用程序就没有在报出任何timeout的错误了。