使用network monitor trace发现应用程序在数据库上执行时的timeout错误
一个奇怪的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的版本可以从这里下载：
收集下来的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的错误了。