症状:
端午发布后,服务器出现大量报错日志,并且平均响应时间不断上升。重启机器后立刻恢复正常,但还是运行一段时间后,响应时间又开始上升。
从报错日志中发现很多DB连接池满的错误。导致这种错误一般有两个原因:
1:SQL 执行完后,DbConnection 及时没有释放。
2:SQL 执行慢,占用了大量 DbConnection 。
通过对代码彻底扫描,发现有几个 DataReader 没有显示关闭的地方。但这些都是运行很久老代码应该不是引用这次现象的原因。修改代码重新上线后的确没有得到改善。
继续找原因:
观察单台服务器的平均响应时间曲线。基本上是按一分钟一个周期上下波动。
对每个接口的平均响应时间曲线分析,发现所有接口的平均响应时间都有上升,再分析每个接口的调用量,除了六一期间,没有明显增加。可以排除是单个接口影响了整体响应时间。
同时对比多个接口的最大响应时间曲线,发现都是按一个频率上下波动,并且和整体平均响应时间的曲线是吻合的。
有规律性的上下波动,我猜测可能是由于什么堵塞,造成线程等待。再从代码上进行排查后,没有发现什么线索。还是找来DUMP 文件进行分析。
!threadpool 显示程序池信息
CPU不高 和 线程数量没有什么异常
!syncblk 显示同步块
发现有40来个线程来等待000000017f636630 这个同步块。51这个线程拥有这个同步块,其它的线程都在等待这个同步块的释放。看到这似乎找到了方向。
~51s 切找到51这个线程
!clrstack 列出当前线程的调用堆栈
51这个线程 正在执行 clearCache这个方法
!clrstack -l 列出当前线程的调用堆栈及其使用的局部变量
可以看到clearCache这个方法有引用 000000017f636630 这个同步块
~52s 切换到其中一个等待线程
可以看也有引用000000017f636630 这个同步块。System.Threading.Monitor.Enter(System.Object) 获取排他锁。
由于~51 clearCache 这个方法内LOCK 了这个对象,造成~52 Validate这方法等待锁的释放。
切换到它几个线程也是同样的情况。
这是引用的框架部门的DLL的两个方法,反编译这个DLL 找到这两个方法。
是一个清除日志的操作,每次清除 n 小时以前的数据。 N小时到当前时间内产生的数据,如果满足 > CountMax ,则一直会执行 这个FOR循环。
而且 remove(i) 会引起LogEntryCache.Count;的值变化,这样每次只能遍历一半。并发量大的情况,会造成每个线程漫长的等待。
并且在执行 ExecuteReader 内部就被锁住了。产生的DataReader还没有return,
DbConnection没有释放,就很有可能造成数据库连接池满。
!dumpstackobjects 打印当前thread的stack中保存的所有托管的object
找到System.Data.SqlClient.SqlCommand 的地址
!do 00000001805619e8 显示Command对象的内容
!do 0000000180561b30 显示SqlConnection
000000017f613c98 _poolGroup 该连接使用的连接池
下面找到这个连接池
!dumpheap –stat 检查当前所有托管类型的统计信息
找到System.Data.ProviderBase.DbConnectionPool
!dumpheap -mt 000007feedd23a98 查看函数表地址中的各个对象信息
!do 0x000000017f614748 显示DbConnectionPool
000000017f613c98 _connectionPoolGroup 这个连接池有14个等待。
更新DLL 后,问题解决。