Windbg 分析線程堵塞


症狀:

端午發布后,服務器出現大量報錯日志,並且平均響應時間不斷上升。重啟機器后立刻恢復正常,但還是運行一段時間后,響應時間又開始上升。

 

 從報錯日志中發現很多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  打印當前threadstack中保存的所有托管的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 后,問題解決。


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM