症狀:
端午發布后,服務器出現大量報錯日志,並且平均響應時間不斷上升。重啟機器后立刻恢復正常,但還是運行一段時間后,響應時間又開始上升。
從報錯日志中發現很多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 后,問題解決。