症狀:
端午釋出後,伺服器出現大量報錯日志,并且平均響應時間不斷上升。重新開機機器後立刻恢複正常,但還是運作一段時間後,響應時間又開始上升。
從報錯日志中發現很多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 後,問題解決。
轉載于:https://www.cnblogs.com/zrhai/p/3784206.html