天天看點

Windbg 分析線程堵塞

症狀:

端午釋出後,伺服器出現大量報錯日志,并且平均響應時間不斷上升。重新開機機器後立刻恢複正常,但還是運作一段時間後,響應時間又開始上升。

Windbg 分析線程堵塞

 從報錯日志中發現很多DB連接配接池滿的錯誤。導緻這種錯誤一般有兩個原因:

1:SQL 執行完後,DbConnection 及時沒有釋放。

2:SQL 執行慢,占用了大量 DbConnection 。

通過對代碼徹底掃描,發現有幾個 DataReader 沒有顯示關閉的地方。但這些都是運作很久老代碼應該不是引用這次現象的原因。修改代碼重新上線後的确沒有得到改善。

繼續找原因:

觀察單台伺服器的平均響應時間曲線。基本上是按一分鐘一個周期上下波動。

Windbg 分析線程堵塞

對每個接口的平均響應時間曲線分析,發現所有接口的平均響應時間都有上升,再分析每個接口的調用量,除了六一期間,沒有明顯增加。可以排除是單個接口影響了整體響應時間。

同時對比多個接口的最大響應時間曲線,發現都是按一個頻率上下波動,并且和整體平均響應時間的曲線是吻合的。

Windbg 分析線程堵塞

有規律性的上下波動,我猜測可能是由于什麼堵塞,造成線程等待。再從代碼上進行排查後,沒有發現什麼線索。還是找來DUMP 檔案進行分析。

!threadpool   顯示程式池資訊

Windbg 分析線程堵塞

CPU不高 和 線程數量沒有什麼異常

!syncblk  顯示同步塊

Windbg 分析線程堵塞

發現有40來個線程來等待000000017f636630 這個同步塊。51這個線程擁有這個同步塊,其它的線程都在等待這個同步塊的釋放。看到這似乎找到了方向。

~51s 切找到51這個線程

!clrstack 列出目前線程的調用堆棧

Windbg 分析線程堵塞

51這個線程 正在執行 clearCache這個方法

!clrstack  -l 列出目前線程的調用堆棧及其使用的局部變量

Windbg 分析線程堵塞

可以看到clearCache這個方法有引用 000000017f636630 這個同步塊

~52s 切換到其中一個等待線程

Windbg 分析線程堵塞

可以看也有引用000000017f636630 這個同步塊。System.Threading.Monitor.Enter(System.Object) 擷取排他鎖。

由于~51 clearCache 這個方法内LOCK 了這個對象,造成~52 Validate這方法等待鎖的釋放。

切換到它幾個線程也是同樣的情況。

這是引用的架構部門的DLL的兩個方法,反編譯這個DLL 找到這兩個方法。

Windbg 分析線程堵塞
Windbg 分析線程堵塞

是一個清除日志的操作,每次清除 n 小時以前的資料。 N小時到目前時間内産生的資料,如果滿足 > CountMax ,則一直會執行 這個FOR循環。

而且 remove(i) 會引起LogEntryCache.Count;的值變化,這樣每次隻能周遊一半。并發量大的情況,會造成每個線程漫長的等待。

并且在執行 ExecuteReader 内部就被鎖住了。産生的DataReader還沒有return, 

DbConnection沒有釋放,就很有可能造成資料庫連接配接池滿。

!dumpstackobjects  列印目前thread的stack中儲存的所有托管的object

找到System.Data.SqlClient.SqlCommand 的位址

Windbg 分析線程堵塞

!do 00000001805619e8  顯示Command對象的内容

Windbg 分析線程堵塞

!do 0000000180561b30 顯示SqlConnection

Windbg 分析線程堵塞

000000017f613c98 _poolGroup 該連接配接使用的連接配接池

下面找到這個連接配接池

!dumpheap –stat 檢查目前所有托管類型的統計資訊

找到System.Data.ProviderBase.DbConnectionPool

Windbg 分析線程堵塞

!dumpheap -mt 000007feedd23a98 檢視函數表位址中的各個對象資訊

Windbg 分析線程堵塞

!do 0x000000017f614748 顯示DbConnectionPool

Windbg 分析線程堵塞

000000017f613c98 _connectionPoolGroup 這個連接配接池有14個等待。

更新DLL 後,問題解決。

轉載于:https://www.cnblogs.com/zrhai/p/3784206.html