記一次 .NET 某上市工業智造 CPU+記憶體+掛死三高分析

一：背景

1. 講故事

上個月有位朋友加wx告知他的程式有掛死現象，詢問如何進一步分析，截圖如下：

看這位朋友還是有一定的分析基礎，可能玩的少，缺乏一定的分析經驗，當我簡單分析之後，我發現這個dump挺有意思的， CPU，記憶體，掛死 三樣全佔，程式悲慘莫過於此。。。

既然找到我，我得想辦法化解他的痛苦，由易到難我們逐一分析這三樣都是因為什麼原因所致？

二：三高分析

1. 掛死原因

根據 40+ 的dump分析經驗，掛死大多是由於某種情況導致執行緒卡死，導致後續請求堆積在 threadpool 中，要想驗證，可以使用 !tp 命令檢視執行緒池佇列。



0:000> !tp

CPU utilization: 81%

Worker Thread: Total: 65 Running: 65 Idle: 0 MaxLimit: 32767 MinLimit: 64

Work Request in Queue: 2831

    Unknown Function: 00007ffffcba1750  Context: 0000022ab04d4a58

    Unknown Function: 00007ffffcba1750  Context: 0000022ab03e4ce8

    ...

    Unknown Function: 00007ffffcba1750  Context: 0000022ab825ec88

    Unknown Function: 00007ffffcba1750  Context: 0000022ab825a458

    Unknown Function: 00007ffffcba1750  Context: 0000022ab8266500

    Unknown Function: 00007ffffcba1750  Context: 0000022ab8268198

    Unknown Function: 00007ffffcba1750  Context: 0000022ab826cb00

    Unknown Function: 00007ffffcba1750  Context: 0000022ab8281578

--------------------------------------

Number of Timers: 0

--------------------------------------

Completion Port Thread:Total: 2 Free: 2 MaxFree: 128 CurrentLimit: 2 MaxLimit: 32767 MinLimit: 64

可以很明顯的看到執行緒池佇列有 2831 個任務堆積，這就導致新進來的請求無法得到處理，所以就出現了掛死現象，接下來就來看看這些執行緒都幹嘛去了，為啥效率那麼低，可以用 ~*e !clrstack 調出所有執行緒棧，截圖如下：

掃了一遍後，發現有很多的 System.Net.HttpWebRequest.GetResponse() 方法，有經驗的朋友應該知道，這又是一個經典的同步http請求過慢導致的程式處理不及的掛死，有些朋友可能好奇，能不能把網址給我扒出來，可以是可以，用 !dso 命令即可。



000000D2FBD3B840 0000023269e85698 System.Text.UTF8Encoding

000000D2FBD3B850 00000236e9dd2cb8 System.String    application/x-www-form-urlencoded

000000D2FBD3B870 0000023269e85698 System.Text.UTF8Encoding

000000D2FBD3B9A8 00000231aa221a38 System.String    uSyncAppxxx

000000D2FBD3B9B8 00000231aa201a70 System.String    VToken={0}&Vorigin={1}&QueryJson={2}

000000D2FBD3B9C0 00000231aa202200 System.String    http://xxx.xxx.com/API/xxx/BusinessCardFolder/Connector/xxx/GetPageList

我去，這url還是一個外網地址，了，本身同步方式就慢，這地址更是雪上加霜哈。。。難怪不卡死

2. cpu爆高分析

從上面的 !tp 輸出中也看出來了，當前 cpu = 81% ，那為什麼會這麼高呢？根據經驗大概就是 lock鎖，GC觸發，死迴圈等情況，可以用排除法。

是 lock 鎖嗎？

可以用命令 !syncblk 看一下同步塊表。



0:000> !syncblk

Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner

  212 0000023ef3cdd028            3         1 0000023ef40efa40 8d70 209   000002396ad93788 System.Object

-----------------------------

Total           297

CCW             3

RCW             4

ComClassFactory 0

Free            139

從輸出看，lock 鎖沒什麼問題，接下來用 !mlocks 命令檢視下其他型別的鎖，看看有沒有什麼新發現。



0:000> !mlocks

Examining SyncBlocks...

Scanning for ReaderWriterLock(Slim) instances...

Scanning for holders of ReaderWriterLock locks...

Scanning for holders of ReaderWriterLockSlim locks...

Examining CriticalSections...

ClrThread  DbgThread  OsThread    LockType    Lock              LockLevel

------------------------------------------------------------------------------

...

0x49       209        0x8d70      thinlock    000002396ad9ba90  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9baa8  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9bac0  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9bad8  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9baf0  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9bb08  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9bb20  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9bb38  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9bb50  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9bb68  (recursion:0)

0x49       209        0x8d70      thinlock    000002396ad9bb80  (recursion:0)

0xe        152        0x8e68      thinlock    0000023669f7e428  (recursion:0)

0x41       208        0x8fb4      thinlock    00000235e9f6e8d0  (recursion:0)

0x17       161        0x9044      thinlock    00000238ea94db68  (recursion:0)

0x16       159        0x911c      thinlock    000002392a03ed40  (recursion:0)

0x47       206        0x9264      thinlock    000002322af08e28  (recursion:0)

我去，發現有大量的 thinlock，而且 DbgThread=209 執行緒居然有 1000 +，截圖如下：

有些朋友可能不知道什麼叫 thinlock，簡單來說，它就是一種耗cpu的內旋鎖，類似 SpinLock，接下來隨便抽一個物件，檢視它的 !gcroot 。



0:000> !gcroot 000002396ad9ba48

Thread 2580:

    000000d2fb0bef10 00007ff806945ab3 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)

        rbp-80: 000000d2fb0bef50

            ->  0000023769dd4008 System.Threading.Thread

            ->  0000023269e776b8 System.Runtime.Remoting.Contexts.Context

            ->  0000023269e773b8 System.AppDomain

            ...

            ->  0000023269ee1e00 System.Threading.TimerCallback

            ->  0000023269ed2d30 System.Web.Caching.CacheExpires

            ->  0000023269ed2c78 System.Web.Caching.CacheSingle

            ->  0000023269ed2ce0 System.Collections.Hashtable

            ->  000002372ab91d90 System.Collections.Hashtable+bucket[]

            ->  00000239ab32fd10 System.Web.Caching.CacheEntry

            ->  000002396ad93748 System.Collections.Concurrent.ConcurrentDictionary`2[[System.String, mscorlib],[xxx].Application.Entity.BaseManage.UserRelationEntity, xxx.Application.Entity]]

            ->  00000239ab2a8248 System.Collections.Concurrent.ConcurrentDictionary`2+Tables[[System.String, mscorlib],[xxx.Application.Entity.BaseManage.UserRelationEntity, xxx.Application.Entity]]

            ->  000002396ad96b80 System.Object[]

            ->  000002396ad9ba48 System.Object

從輸出資訊看,這個 thinlock 來自於 ConcurrentDictionary 字典內部，接下來我們 dump 出這個字典，使用 !mdt 命令。



0:148> !mdt 000002396ad93748

000002396ad93748 (System.Collections.Concurrent.ConcurrentDictionary`2[[System.String, mscorlib],[xxx.Application.Entity.BaseManage.UserRelationEntity, xxx.Application.Entity]])

    m_tables:00000239ab2a8248 (System.Collections.Concurrent.ConcurrentDictionary`2+Tables[[System.String, mscorlib],[xxx.Application.Entity.BaseManage.UserRelationEntity, xxx.Application.Entity]])

    m_comparer:NULL (System.Collections.Generic.IEqualityComparer`1[[System.__Canon, mscorlib]])

    m_growLockArray:true (System.Boolean)

    m_keyRehashCount:0x0 (System.Int32)

    m_budget:0x213 (System.Int32)

    m_serializationArray:NULL (System.Collections.Generic.KeyValuePair`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]][])

    m_serializationConcurrencyLevel:0x0 (System.Int32)

    m_serializationCapacity:0x0 (System.Int32)

0:148> !mdt 00000239ab2a8248

00000239ab2a8248 (System.Collections.Concurrent.ConcurrentDictionary`2+Tables[[System.String, mscorlib],[xxx.Application.Entity.BaseManage.UserRelationEntity, xxx.Application.Entity]])

    m_buckets:0000023e9a2477e8 (System.Collections.Concurrent.ConcurrentDictionary`2+Node[[System.String, mscorlib],[xxx.Application.Entity.BaseManage.UserRelationEntity, xxx.Application.Entity]][], Elements: 543997)

    m_locks:000002396ad96b80 (System.Object[], Elements: 1024)

    m_countPerLock:00000239aa8472c8 (System.Int32[], Elements: 1024)

    m_comparer:0000023269e782b8 (System.Collections.Generic.GenericEqualityComparer`1[[System.String, mscorlib]])

從上面資訊看，這個字典有 54.3 w 條記錄，為啥這麼大，而且還有 1024 個 lock，有點意思，我們扒一下原始碼看看。

從原始碼看，內部確實有一個 lock[] 陣列，那到底是什麼操作引發了遍歷 locks[]，要想尋找答案，可以在所有執行緒棧上尋找 ConcurrentDictionary 關鍵詞。



OS Thread Id: 0x2844 (163)

        Child SP               IP Call Site

000000d2fb83abb8 00007ff80a229df8 [GCFrame: 000000d2fb83abb8]

000000d2fb83aca0 00007ff80a229df8 [GCFrame: 000000d2fb83aca0]

000000d2fb83acd8 00007ff80a229df8 [HelperMethodFrame: 000000d2fb83acd8] System.Threading.Monitor.Enter(System.Object)

000000d2fb83add0 00007ff80693ea56 System.Collections.Concurrent.ConcurrentDictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].AcquireLocks(Int32, Int32, Int32 ByRef)

000000d2fb83ae20 00007ff806918ef2 System.Collections.Concurrent.ConcurrentDictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].AcquireAllLocks(Int32 ByRef)

000000d2fb83ae60 00007ff8069153f9 System.Collections.Concurrent.ConcurrentDictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].GetValues()

000000d2fb83aee0 00007ff7ae17d8ec xxx.Util.DataHelper.ToEnumerable[[System.__Canon, mscorlib],[System.__Canon, mscorlib]](System.Collections.Concurrent.ConcurrentDictionary`2<System.__Canon,System.__Canon>)

000000d2fb83af20 00007ff7ad125241 xxx.Application.Code.CacheHelper.GetCaches[[System.__Canon, mscorlib],[System.__Canon, mscorlib]](System.String)

000000d2fb83afa0 00007ff7ad12513b xxx.Application.Code.CacheHelper.GetCaches[[System.__Canon, mscorlib]](System.String)

000000d2fb83b000 00007ff7b10199e5 xxx.Application.Cache.CacheHelper.GetUserRelations()

從執行緒棧上看，發現了有近20處如上的程式碼，可以看出程式在呼叫 GetCaches 方法的時候觸發了 ConcurrentDictionary 的lock鎖從而卡住，接下來我們看一下 xxx.Application.Cache.CacheHelper.GetUserRelations() 原始碼到底做了什麼？



public static IEnumerable<UserRelationEntity> GetUserRelations()

{

	return xxx.Application.Code.CacheHelper.GetCaches<UserRelationEntity>("xxx.BaseManage-UserRelation");

}

protected static IEnumerable<T> GetCaches<T>(string cacheKeyName)

{

	return GetCaches<T, string>(cacheKeyName);

}

private static IEnumerable<T> GetCaches<T, TKey>(string cacheKeyName)

{

	return GetConcurrentDictionaryCache<T, TKey>(cacheKeyName)?.ToEnumerable();

}

public static IEnumerable<T> ToEnumerable<TKey, T>(this ConcurrentDictionary<TKey, T> dics)

{

	return dics.Values;

}

從原始碼邏輯看，程式每次呼叫快取最終都會呼叫 dics.Values , 我很好奇它的框架邏輯是什麼樣的？截圖如下：

大家有沒有發現，每次 dict.Values 時都要執行 1024 次 Monitor.Enter(locks[i], ref lockTaken);，也就是 1024 次的內旋鎖，這就是cpu高的一個關鍵因素。

3. 記憶體爆高原因

最後一個問題是記憶體為啥會爆高？細心的朋友應該會發現剛才那個 GetValues 中有一個奇怪的邏輯，我再貼一下程式碼：



private ReadOnlyCollection<TValue> GetValues()

{

	int locksAcquired = 0;

	try

	{

		AcquireAllLocks(ref locksAcquired);

		int countInternal = GetCountInternal();

		if (countInternal < 0)

		{

			throw new OutOfMemoryException();

		}

		List<TValue> list = new List<TValue>(countInternal);

		for (int i = 0; i < m_tables.m_buckets.Length; i++)

		{

			for (Node node = m_tables.m_buckets[i]; node != null; node = node.m_next)

			{

				list.Add(node.m_value);

			}

		}

		return new ReadOnlyCollection<TValue>(list);

	}

	finally

	{

		ReleaseLocks(0, locksAcquired);

	}

}

有沒有發現，每一次 GetValues 時都會生成一個 54.3w 大小的新List，請注意這個 list 是新生成的，不是 ConcurrentDictionary 上的引用，這就很坑了，每呼叫一次，LOH上就會來一個這麼大的List，你說記憶體暴增不暴增？？？

三：總結

總的來說，這苦逼的三高有下面兩個因素造成。

使用了同步的 HttpRequest 方式並使用了外網url導致程式掛死。

優化措施：使用非同步方式

巨坑的 ConcurrentDictionary.Values 導致記憶體，cpu 爆高。

我想很多朋友都沒想到: ConcurrentDictionary.Values 有這麼大的一個坑，這就讓我聯想起了執行緒不安全的 Dictionary.Values 是怎麼做的？

public ValueCollection Values

{

    [__DynamicallyInvokable]

    get

    {

        if (values == null)

        {

            values = new ValueCollection(this);

        }

        return values;

    }

}

public sealed class ValueCollection

{

    public ValueCollection(Dictionary<TKey, TValue> dictionary)

    {

        if (dictionary == null)

        {

            ThrowHelper.ThrowArgumentNullException(ExceptionArgument.dictionary);

        }

        this.dictionary = dictionary;

    }

}

可以很明顯的看到它並沒有生成新的list，所以優化措施如下：

拒絕使用 ConcurrentDictionary.Values，採用 lock + Dictionary 。
如果硬要用 ConcurrentDictionary ，請將 Query 條件送下去，而不是使用 Values 做全量拉取再查詢，減少記憶體無畏佔用。

最後上一個小彩蛋，將分析結果給了這位朋友之後，朋友想讓我上門分析，第一次遇到。。。太猝不及防啦

記一次 .NET 某上市工業智造 CPU+記憶體+掛死 三高分析