记一次 .NET 某企业ECM内容管理系统 内存暴涨分析

一：背景

1. 讲故事

这个dump是去年一个朋友发给我的，让我帮忙分析下为什么内存暴涨，当时由于相关知识的缺乏，分析了一天也没找出最后的原因，最后就不了了之的，直到最近我研究了下 CancellationToken 和 CompositeChangeToken 的底层玩法，才对这个问题有了新的视角，这篇就算是迟来的解读吧。
二：内存暴涨分析

1. 为什么会暴涨

由于是在 linux 上采摘下来的dump，所以用 !maddress -summary 命令观察进程的内存布局，输出如下：

1. +-------------------------------------------------------------------------+
2. | Memory Type            |          Count |         Size |   Size (bytes) |
3. +-------------------------------------------------------------------------+
4. | Stack                  |          1,101 |       8.67gb |  9,305,092,096 |
5. | PAGE_READWRITE         |          1,371 |       1.13gb |  1,216,679,936 |
6. | GCHeap                 |             64 |     790.70mb |    829,108,224 |
7. | Image                  |          1,799 |     257.44mb |    269,944,832 |
8. | HighFrequencyHeap      |            797 |      49.85mb |     52,269,056 |
9. | LowFrequencyHeap       |            558 |      38.32mb |     40,185,856 |
10. | LoaderCodeHeap         |             23 |      33.53mb |     35,155,968 |
11. | HostCodeHeap           |             15 |       2.63mb |      2,752,512 |
12. | ResolveHeap            |              2 |     732.00kb |        749,568 |
13. | DispatchHeap           |              2 |     452.00kb |        462,848 |
14. | IndirectionCellHeap    |              5 |     280.00kb |        286,720 |
15. | PAGE_READONLY          |            124 |     253.50kb |        259,584 |
16. | CacheEntryHeap         |              4 |     228.00kb |        233,472 |
17. | LookupHeap             |              4 |     208.00kb |        212,992 |
18. | PAGE_EXECUTE_WRITECOPY |              5 |      48.00kb |         49,152 |
19. | StubHeap               |              1 |      12.00kb |         12,288 |
20. | PAGE_EXECUTE_READ      |              1 |       4.00kb |          4,096 |
21. +-------------------------------------------------------------------------+
22. | [TOTAL]                |          5,876 |      10.95gb | 11,753,459,200 |
23. +-------------------------------------------------------------------------+

复制代码

这卦象一看吓一跳，总计内存 10.95G，Stack就独吃 8.67G，并且 Count=1101 也表明了当前有 1101 个线程，这么高的线程数一般也表示出大问题了。。。
2. 为什么线程数这么高

要想找到这个答案，可以用 ~*e !clrstack 观察每个线程都在做什么，发现有大量的 Sleep 等待，输出如下：

1. 0:749> ~*e !clrstack
2. ...
3. OS Thread Id: 0x6297 (932)
4.         Child SP               IP Call Site
5. 00007FE9D7FBB508 00007ffa5f564e2b [HelperMethodFrame: 00007fe9d7fbb508] System.Threading.Thread.SleepInternal(Int32)
6. 00007FE9D7FBB650 00007ff9e9ac113f System.Threading.SpinWait.SpinOnceCore(Int32) [/_/src/System.Private.CoreLib/shared/System/Threading/SpinWait.cs @ 242]
7. 00007FE9D7FBB6E0 00007ff9ee55ffd8 System.Threading.CancellationTokenSource.WaitForCallbackToComplete(Int64) [/_/src/System.Private.CoreLib/shared/System/Threading/CancellationTokenSource.cs @ 804]
8. 00007FE9D7FBB710 00007ff9eea0817d Microsoft.Extensions.Primitives.CompositeChangeToken.OnChange(System.Object) [/_/src/libraries/Microsoft.Extensions.Primitives/src/CompositeChangeToken.cs @ 128]
9. 00007FE9D7FBB760 00007ff9e9adc75d System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean) [/_/src/System.Private.CoreLib/shared/System/Threading/CancellationTokenSource.cs @ 724]
10. 00007FE9D7FBB7D0 00007ff9e9ab8d61 System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 315]
11. 00007FE9D7FBB810 00007ff9e9abd8dc System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2421]
12. 00007FE9D7FBB890 00007ff9e9ab1039 System.Threading.ThreadPoolWorkQueue.Dispatch() [/_/src/System.Private.CoreLib/shared/System/Threading/ThreadPool.cs @ 699]
13. 00007FE9D7FBBCA0 00007ffa5e6632df [DebuggerU2MCatchHandlerFrame: 00007fe9d7fbbca0]
14. ...

复制代码

仔细阅读卦中的代码，大概知道问题出在了 CompositeChangeToken.OnChange 里，接下来翻一遍源代码，输出如下：

1. private static void OnChange(object state)
2. {
3.     CompositeChangeToken compositeChangeToken = (CompositeChangeToken)state;
4.     if (compositeChangeToken._cancellationTokenSource == null)
5.     {
6.         return;
7.     }
8.     lock (compositeChangeToken._callbackLock)
9.     {
10.         try
11.         {
12.             compositeChangeToken._cancellationTokenSource.Cancel();
13.         }
14.         catch
15.         {
16.         }
17.     }
18.     List<IDisposable> disposables = compositeChangeToken._disposables;
19.     for (int i = 0; i < disposables.Count; i++)
20.     {
21.         disposables[i].Dispose();
22.     }
23. }
25. private void WaitForCallbackIfNecessary()
26. {
27.     CancellationTokenSource source = _node.Partition.Source;
28.     if (source.IsCancellationRequested && !source.IsCancellationCompleted && source.ThreadIDExecutingCallbacks != Environment.CurrentManagedThreadId)
29.     {
30.         source.WaitForCallbackToComplete(_id);
31.     }
32. }
34. internal void WaitForCallbackToComplete(long id)
35. {
36.     SpinWait spinWait = default(SpinWait);
37.     while (ExecutingCallback == id)
38.     {
39.         spinWait.SpinOnce();
40.     }
41. }

复制代码

上面的代码可能有些人看不懂是什么意思，我先补充一下序列图。

接下来根据代码将上面的序列化图落地一下

• 自定义Token在哪里？
  

这个可以深挖 CallbackNode 中的 CallbackState 字段，可以看到是 CancellationChangeToken ，截图如下：

• OnChange 触发在哪里
  

根据 CompositeChangeToken 底层机制，这个组合变更令牌 在所有的子Token中都是共享的，在各个线程中我们都能看得到，截图如下：

• CancellationTokenRegistration 在哪里
  

这个类是我们回调函数的登记类，从 compositeChangeToken._disposables 中大概知道有 4 个回调函数，截图如下：

接下来将 dump 拖到 vs 中，观察发现都卡死在 for 对 Dispose 遍历上，截图如下：

为什么都会卡死在 disposables.Dispose(); 上？这是我们接下来要探究的问题，根据上面代码中的 ThreadIDExecutingCallbacks != Environment.CurrentManagedThreadId 和 ExecutingCallback == id 大概也能猜出来， A线程 要释放的节点正在被 B线程 持有，可能 B线程 要释放的节点正在被 A线程 持有，所以大概率引发了死锁情况。。。
3. 真的是死锁吗

要想找到是不是真的发生了死锁，可以由果推因将四个自定义的Token下的 CancellationChangeToken.cts.ThreadIDExecutingCallbacks 字段给找到，截图如下：

从卦中可以看到四个节点分别被 726,697,722,774 这4个线程持有，接下来切到 726号线程看下它此时正在做什么，截图如下：

从卦中可以看到726号线程已持有 disposables[0] ，正等待 697号线程持有的 disposables[1] 释放，接下来切到 697号线程，看下它此时正在做什么，截图如下：

从卦中可以看到，697号线程持有 disposables[1] ，正等待 726 号线程持有的 disposables[0] 释放。
到这里就呈现出了经典的的死锁！
4. 为什么会出现死锁

很显然这个死锁是多线程操控共享的 compositeChangeToken.disposables[] 数组导致的，而且据当时朋友反馈并没有用户代码故意为之，现在回头看应该是 NET 3.1.20 内部的bug导致的。

1. 0:749> lmDvmlibcoreclr
3.     Image path: /usr/share/dotnet/shared/Microsoft.NETCore.App/3.1.20/libcoreclr.so

复制代码

为了验证这个这个说法，我使用了最新的 .NET 3.1.32 版本，发现这里多了一个 if 判断，截图如下：

不要小看这里面的if，因为一旦有人执行了 compositeChangeToken._cancellationTokenSource.Cancel() 方法，那么 compositeChangeToken._cancellationTokenSource.IsCancellationRequested 必然就是 true，可以避免后续有人无脑的对 disposables 遍历。
所以最好的办法就是升级 coreclr 版本观察。
三：总结

在高级调试的旅程中，会遇到各种 牛鬼蛇神，奇奇怪怪，不可思议的奇葩问题，玩.NET高级调试并不是能 fix bug，但确实能真真切切的缩小包围圈，毕竟解铃还须系铃人！

来源：程序园用户自行投稿发布，如果侵权，请联系站长删除
免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！