问题
对某个库新增了一个订阅节点,然后需要把一些应用切到新订阅库,以分散负载。当应用切换后,有一个应用每次启动不到30秒,总是报超时的错误,而error log中又没有任何记录:
Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.The statement has been terminated.
但是切回连接到原来的订阅库就不会超时。
分析
1. 自先排查连接超时,找运维看连接配置,连接超时设定为90秒。排除之。
2. 排查语句超时,找到开发,说找不到历史版本的源码了,也就没有办法查看SqlCommand.CommandTimeout的设定值,无法继续排查。
3. 1,2无果的情况下,用XE捕获一下error信息,这个默认的system_health session就有:
Network error code 0x2746 occurred while establishing a connection; the connection has been closed. This may have been caused by client or server login timeout expiration.
Time spent during login: total 2407 ms, enqueued 0 ms, network writes 0 ms, network reads 2407 ms, establishing SSL 0 ms, negotiating SSPI 0 ms, validating login 0 ms,
including user-defined login processing 0 ms.
error code 0x2746 就是10054,使用NET HELPMSG 查看,结果为:Connection forcibly closed by remote host.
好了,到此为止,我断定问题出在应用端。于是找上开发,运维一起讨论,看他们能否详细排查应用端,结论是:没办法。
4. 难道真的没有办法了?
既然超时信息能返回到应用端,那么我可以抓包,看到底出什么事了。于是使用Network Monitor一抓:
从抓到的信息来看,图中选中的行,正是timeout的。它前一条记录TDS:SQLBatch 从应用端发到服务端,过了一会儿,应用端就超时了。
这就很明显了,应用端发了一个Batch给数据库执行,等了一下它自己就说:我超时了。问题就出在这里,它发的是什么语句,执行了多久,造成了超时。
5. 用Profiler跟踪:
此Batch执行大约用时20s,也得到了具体的语句。
6. 但是为什么切换到原来的订阅库就不超时,连接新的订阅库就会超时呢?
将5.中抓到的语句分别在两个实例上执行,发现新的订阅库返回8W+行的数据,而旧的只返回6行数据且神速。
再进一步分析语句,原来旧的订阅库中,有一个非订阅表,表中有大量用于筛选的数据;但新订阅库只有这个表,没有数据。
于是将此表数据导入到新订阅库中的对应表中,两者查询的一结果一致了,应用也不超时了。据此推断应用代码中SqlCommand.CommandTimeout绝对小于20s.
总结:
1. 10054错误一个很出名的错误,原因有多种,比较难排查的一个问题。
2. 如果能这在2. 一步就能确认SqlCommand.CommandTimeout的设定值,并做相应调试排查,将会省了很多事。源码管理的重要性啊!
3. 做事得细心,新增订阅后,我只对比两者的对象是否一样,如果也核对了表中行数是否一样,也就不会发生这事了。