文章出處

在端午節放假的三天中，我對正在開發的 Service 進行了 LoadTest，嘗試在增大壓力的條件下發現問題。

該 Service 為獨立進程的 WCF 服務，宿主于 WindowsService，其接收其他 Service 的調用，并根據業務流程調用不同的依賴 Service。

問題現象

果真，假期歸來，問題來了。內存正常在 200M 左右，已經膨脹到 4.5G，同時正常線程數為 40-60 左右，已經占用了 560 個。

基于在測試之前已經準備好了 PerformanceCounter 記錄，從報表數據來看，CPU 使用率不高，并且仍然在偶爾活躍，可以猜測只是部分業務 Block，而非全部。

在此期間，內存不斷攀升，而且比想象的要快。

但奇怪的是，線程數在 6 月 8 日 7:30 左右才開始爆發。

所以大概可以分析，內存的增加與線程的增加，沒有之間的聯系，線程數雖在 500 以上，但按照業務代碼核算，不至于產生 4.5G 以上的內存使用。

所以猜測，應該有兩個問題：

  1. 在代碼某處有持續的內存泄漏。
  2. 在代碼某處有單點故障導致 Block 線程。

分析內存泄漏

好的消息是，進程還活著，雖然不再進行正經的業務。此時，祭出神器 WinDbg，嘗試看看內存中有什么。

!dumpheap -stat

  • MT ：對應 Method Table 地址。
  • Count : 該對象的數量。
  • TotalSize ：該對象的總大小，Bytes。

TriggerHit和TriggerProgress都是業務類型，可以大概看一下TriggerHit類型的大小，使用：

!dumpheap -mt 000007ff006775a0

!dumpobj 0000000005cbbf78

可以明確判斷，每個AsyncToken實例只占48Bytes。而其為ConcurrentDictionary中的一個Node，代表一個KeyValue鍵值對。

綜合以上可以看出，幾種類型 TriggerProgress、TriggerHit、long、AsyncToken 類型最多。從業務設計上看 TriggerProgress/TriggerHit 業務類實例的個數是相同的，從圖上看也是相同的，但數量肯定不至于有507萬個。每個類型的占用內存大概在240M以上。而有差不多數量的 AsyncToken 類型，占用也在240M左右。而 long 類型，存放在 ConcurrentDictionary 中，應該是作為某種索引，居然有1000萬條，空間占用480M以上。這幾個類型的占用總和已經達到了3G左右。所以說，這里應該是內存泄漏的根源。

此時，查看對應的數據庫表 Triggers，

居然有700多萬條數據處在Enabled狀態。此處的Trigger是個業務概念，其代表該Service與另外一個Service之間的Transaction，如果其為活躍，則證明在所依賴的Service并沒有明確回復該Transaction已結束。而從業務設計角度，每秒會產生100-200個Transaction，每個Transaction通常在5分鐘左右的時間結束。進一步在Service的日志Log中確認是否有Exception出現，排除處理Transaction異常的情況，發現沒有。也就是說，有大量的Transaction未接收到回復，所依賴的Service應該出了問題。

走到此處，在LoadTest中內存泄漏的問題算是被確認了，而后來經過與相應的Service開發人員溝通，確認所依賴的Service確實有性能問題，因為在Load很高的情況下，發送的Transaction數量已經超過了對方Service承受的能力。后續的補充解決辦法是為Transaction增加Timeout超時檢測。

好，問題解決一個，線程數高的問題還沒有解決，前面已經描述了，內存高與線程多沒有關系。那么，那560個線程每個走在做什么工作呢？

分析線程使用

顯然需要繼續使用WinDbg，因為此時使用ProcessExplorer只能幫助確認線程在使用那些DLLs，沒有更多幫助。

由于有500多個線程，所以也不知道從哪個開始，只能從頭一個一個來。一般1-10可能是進程啟動時啟用的線程，比如MainThread、GC回收線程等。同時，業務中的一些常規Timer也會先啟動占用線程。

當查到第22個線程時，

~22 e !clrstack

這個很有幫助，發現第22個線程在 SemaphoreSlim.Wait() 等待一個信號量釋放，而其為類 SmartQueue 中的代碼。還好加了PDB文件，直接顯示到 SmartQueue.cs 的第 301 行。直接看看代碼，

發現這句代碼在等待信號量的釋放，并且沒有指定超時時間，所以如果信號量在占用線程不被釋放，這里將一直阻塞著。那這是一個被阻塞的線程，而不是引發阻塞的線程。

下一個線程，23號線程也在做同樣的事情，等待信號量釋放，所以猜測有很多線程在等待同一個信號量釋放。

問題是，系統中有至少10個SmartQueue在工作，而此處無法看出是哪個SmartQueue被阻塞了。但根據業務設計和配置文件中的配置，

每個SmartQueue中最多啟160個線程，而這個Queue的配置已經是最大的了，其他均小于160。這樣看來，達到560，還不是一個SmartQueue在努力。

問題復雜了，一時看不出究竟，只能繼續查看。當查到第30號線程時，

希望來了，這個調用占說明，在方法ObtainXXX中，正在Monitor.Enter(object)，也就是一個lock在嘗試鎖定對象。此時繼續查看線程調用棧，40/50/100/200/300/400/500線程均Block在ObtainXXX方法中。

PDB信息中已經給出的代碼行，

這里__activeXXX是一個ConcurrentDictionary，這里已經進行了DoubleCheck檢測，也就是獲得鎖的線程需要檢測是否該ID已經在其他線程中增加了。但調用這個ObtainXXX方法的代碼有8處，并且在不同的業務規則中，所以確實可以發生在不同的SmartQueue中的線程中，也驗證了上面的猜測。

那么，問題是，既然一個線程得到了鎖，而其不釋放這個鎖，那么就是說{}代碼中應該有可阻塞調用。

發現代碼中，除了Log，只有一句代碼，就是這個LoadXXXByID，其功能就是從數據庫中獲取數據并生成對象實例。

此處我開始疑惑，Service訪問數據庫使用EntityFramework，此處針對這個業務對象，只有兩種操作，

  • 如果數據庫中不存在此業務對象ID，則Insert一條新的。
  • 如果數據庫中存在此業務對象ID，則通過Select讀取數據構造業務對象。

業務代碼簡寫為：

      Balance storedBalance = Repository.Balance.QueryWithPC()
        .SingleOrDefault(p => p.RelatedId == xxx);

      if storedBalance == null)
      {
        storedBalance = CreateBalanceToRepository(xxx);
      }

這能產生死鎖？

分析數據庫

走到這一步，開始關注數據庫了。因為，感覺Insert操作會產生表級鎖，阻塞所有Select操作，Update操作可能產生多種類型的鎖，但Insert/Update會很快處理完畢釋放鎖。Select操作，默認EntityFramework并不加QueryHint，所以默認查詢隔離級別為ReadCommitted，即使這樣，查詢只會變慢，但不會死鎖。所以，有些想不通。

先查看了針對數據庫訪問定制的PerformanceCounter，

發現在發生故障之前，CRUD操作均在0.1秒以下。在發生故障的那個時間點，針對Balance表的Insert操作的時長已經達到了60秒的量級，而Select操作也已經平均在5秒以上。

到底發生了什么？

SQL Server Management Studio 提供了些默認的報表，先看看。發現一張有用的報表 Top Transactions by Locks Count，

貌似Triggers表有死鎖出現，而業務上，Balance與Trigger是一對多的關系。

查看Trigger表的PerformanceCounter監控記錄，

Trigger這張數據庫表，在同樣的時間也發生了類似的訪問時間異常。

SELECT REQUEST_MODE, REQUEST_TYPE, REQUEST_SESSION_ID 
FROM sys.dm_tran_locks
WHERE RESOURCE_TYPE = 'OBJECT'
AND RESOURCE_ASSOCIATED_ENTITY_ID =(SELECT OBJECT_iD('Triggers'))

用上面這個SQL查詢確認Triggers表在SessionID=77上發生了IX類型的鎖，不釋放。

并且使用 sp_who2 確認這個session是由我們的Service保持的，因為有多個Service在使用同一個數據庫。

我在Google上搜索到了一個可以查看具體鎖內容的SQL，

SELECT  L.request_session_id AS SPID, 
    DB_NAME(L.resource_database_id) AS DatabaseName,
    SC.name AS SchemaName,
    O.Name AS LockedObjectName, 
    P.object_id AS LockedObjectId, 
    L.resource_type AS LockedResource, 
    L.request_mode AS LockType,
    ST.text AS SqlStatementText,        
    ES.login_name AS LoginName,
    ES.host_name AS HostName,
    TST.is_user_transaction as IsUserTransaction,
    AT.name as TransactionName,
    CN.auth_scheme as AuthenticationMethod
FROM    sys.dm_tran_locks L
    JOIN sys.partitions P ON P.hobt_id = L.resource_associated_entity_id
    JOIN sys.objects O ON O.object_id = P.object_id
    JOIN sys.schemas SC ON O.schema_id = SC.schema_id
    JOIN sys.dm_exec_sessions ES ON ES.session_id = L.request_session_id
    JOIN sys.dm_tran_session_transactions TST ON ES.session_id = TST.session_id
    JOIN sys.dm_tran_active_transactions AT ON TST.transaction_id = AT.transaction_id
    JOIN sys.dm_exec_connections CN ON CN.session_id = ES.session_id
    CROSS APPLY sys.dm_exec_sql_text(CN.most_recent_sql_handle) AS ST
WHERE   resource_database_id = db_id()
ORDER BY SchemaName

查詢結果：

從SqlStatementText的樣子可以看出，這些SQL基本上就是EntityFramework生成的。進而總結所有對Trigger表的操作SQL，

Insert Trigger:

insert [Triggers]([BalanceID], [Origin], [Offset], [Target], [TriggerId], [Category], [CreatedTime], [LastUpdatedTime], [Enabled])
values (@0, @1, @2, @3, @4, @5, @6, @7, @8)
select [ID]
from [Triggers]
where @@ROWCOUNT > 0 and [ID] = scope_identity()',N'@0 bigint,@1 bigint,@2 bigint,@3 bigint,@4 bigint,@5 smallint,@6 datetime2(7),@7 datetime2(7),@8 bit',@0=14,@1=0,@2=0,@3=2000,@4=635062714505193632,@5=0,@6='2013-06-08 07:00:19.8322818',@7='2013-06-08 07:00:19.8322818',@8=1

Update Trigger:

update [Triggers]
set [BalanceID] = @0, [Origin] = @1, [Offset] = @2, [Target] = @3, [TriggerId] = @4, [Category] = @5, [CreatedTime] = @6, [LastUpdatedTime] = @7, [Enabled] = @8
where ([ID] = @9)
',N'@0 bigint,@1 bigint,@2 bigint,@3 bigint,@4 bigint,@5 smallint,@6 datetime2(7),@7 datetime2(7),@8 bit,@9 bigint',@0=14,@1=0,@2=0,@3=266,@4=635062714505193629,@5=3,@6='2013-06-08 07:00:19.8292815',@7='2013-06-08 07:00:37.1550139',@8=0,@9=111

Select Trigger:

SELECT 
[Extent1].[ID] AS [ID], 
[Extent1].[BalanceID] AS [BalanceID], 
[Extent1].[Origin] AS [Origin], 
[Extent1].[Offset] AS [Offset], 
[Extent1].[Target] AS [Target], 
[Extent1].[TriggerId] AS [TriggerId], 
[Extent1].[Category] AS [Category], 
[Extent1].[CreatedTime] AS [CreatedTime], 
[Extent1].[LastUpdatedTime] AS [LastUpdatedTime], 
[Extent1].[Enabled] AS [Enabled]
FROM [Triggers] AS [Extent1]
WHERE ([Extent1].[BalanceID] = @p__linq__0) AND ([Extent1].[Enabled] = 1) AND ([Extent1].[LastUpdatedTime] > @p__linq__1)',N'@p__linq__0 bigint,@p__linq__1 datetime2(7)',@p__linq__0=22,@p__linq__1='2013-06-08 06:15:56.6259518'

這些SQL都已經是簡單到不能再簡單的SQL了，但根據上圖描述，在多個Key上產生了X鎖，在多個Page上產生了IX鎖，而我猜測就是這個IX鎖阻塞了所有操作。

但，我還是不知道為什么會產生DeadLock。我只能猜測，一個Update在把持一個Key-X鎖，而另一個Update把持著Page-IX鎖，他們互相等，而Select在等S鎖，并等待X、IX結束。

然后，我嘗試了一個很stupid的操作，Kill 77。我把這個session給kill掉了，瞬間，service進程沒了。我破壞了現場。

我以為，然后就沒有然后了。

是的，在進程死之前，居然打了句Log，真給力啊。至少它明確的告訴了我，“An existing connection was forcibly closed by the remote host.”。這就是我的Kill操作。

而且，其證明了這個session阻塞在 UnitOfWork.Commit() 方法上，也就是最終的 DbContext.SaveChanges() 上。

而這個操作是在Update這個Triggers表，也就是Transaction在這里產生了DeadLock最終沒有返回，導致此處代碼一直被Block，進而沒有釋放lock(object)，進而阻塞線程，并阻止了其他線程的訪問。

最后，我做了些更改，當獲取 Repository<Trigger> 時，增加 TransactionScope，并指定 ReadUncommitted。

    private static T Get<T>() where T : class
    {
      T obj = default(T);

      using (var transactionScope = new TransactionScope(
        TransactionScopeOption.RequiresNew,
        new TransactionOptions()
        {
          IsolationLevel = IsolationLevel.ReadUncommitted
        }))
      {
        obj = UnityContainerDispatcher.GetContainer().Resolve<T>();
        transactionScope.Complete();
      }

      return obj;
    }

在新的一輪測試中，相同 Load 下，DeadLock 沒有再產生，只能說 "貌似" 解決了問題。


文章列表


不含病毒。www.avast.com
arrow
arrow
    全站熱搜
    創作者介紹
    創作者 大師兄 的頭像
    大師兄

    IT工程師數位筆記本

    大師兄 發表在 痞客邦 留言(0) 人氣()