一次SQL Server 10054 Troubleshooting

时间:2023-03-09 19:11:47
一次SQL Server 10054 Troubleshooting

问题

对某个库新增了一个订阅节点,然后需要把一些应用切到新订阅库,以分散负载。当应用切换后,有一个应用每次启动不到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就有:

一次SQL Server 10054 Troubleshooting

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一抓:

一次SQL Server 10054 Troubleshooting

从抓到的信息来看,图中选中的行,正是timeout的。它前一条记录TDS:SQLBatch 从应用端发到服务端,过了一会儿,应用端就超时了。

这就很明显了,应用端发了一个Batch给数据库执行,等了一下它自己就说:我超时了。问题就出在这里,它发的是什么语句,执行了多久,造成了超时。

5. 用Profiler跟踪:

一次SQL Server 10054 Troubleshooting

此Batch执行大约用时20s,也得到了具体的语句。

6. 但是为什么切换到原来的订阅库就不超时,连接新的订阅库就会超时呢?

将5.中抓到的语句分别在两个实例上执行,发现新的订阅库返回8W+行的数据,而旧的只返回6行数据且神速。 

再进一步分析语句,原来旧的订阅库中,有一个非订阅表,表中有大量用于筛选的数据;但新订阅库只有这个表,没有数据。

于是将此表数据导入到新订阅库中的对应表中,两者查询的一结果一致了,应用也不超时了。据此推断应用代码中SqlCommand.CommandTimeout绝对小于20s.

总结:

1. 10054错误一个很出名的错误,原因有多种,比较难排查的一个问题。

2. 如果能这在2. 一步就能确认SqlCommand.CommandTimeout的设定值,并做相应调试排查,将会省了很多事。源码管理的重要性啊!

3. 做事得细心,新增订阅后,我只对比两者的对象是否一样,如果也核对了表中行数是否一样,也就不会发生这事了。