ASP.NET 挂起 - 通用字典并发问题导致 GC 死锁

Posted 2023-04-13

技术标签:

【中文标题】ASP.NET 挂起 - 通用字典并发问题导致 GC 死锁【英文标题】：ASP.NET Hang - Generic Dictionary concurrency issues causes GC deadlock 【发布时间】：2013-01-28 01:59:31 【问题描述】：

在上个月，我们的 ASP.NET Web 应用程序停止响应请求，我们不得不重置应用程序池以使其恢复。

我们无法确定问题的确切原因，因为服务器的事件日志中没有错误。该网站只是停止响应。

因此，在 Tess Ferrandez 的博客条目的帮助下，我们一直在使用 WinDbg 来尝试分析在站点没有响应时进行的内存转储：GC Hangs 和 High CPU Hang

通过运行!threadpool，我可以看到以下内容：

CPU utilization: 81%
Worker Thread: Total: 10 Running: 8 Idle: 2 MaxLimit: 400 MinLimit: 160
Work Request in Queue: 1930
--------------------------------------
Number of Timers: 72
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 8 CurrentLimit: 0 MaxLimit: 400 MinLimit: 120

根据 Tess 在hang blog post中的说法，这表明我们陷入了垃圾收集的中间（通常需要几纳秒的时间），因为处理器显示 81%这是 .NET 框架在垃圾收集时将其设置为的内容。它被设置为这个，因为当这个值大于 80% 时不能产生新的线程。此外 - 您可以看到队列中有 1930 个请求，即使可能的 400 个工作线程中只有 10 个。

通过运行!threads 命令，我可以看到两个线程的PreEmptive GC 设置为禁用：

                                   PreEmptive   GC Alloc                Lock
       ID  OSID ThreadOBJ    State GC           Context       Domain   Count APT Exception
  10    1  18bc 00000000001b9710   1008220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  16    2   e68 00000000001c0900      b220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Finalizer)
  18    4  1118 00000000001df300   1009220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  19    5  1560 00000000001e9068   100a220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  20    6  11d0 00000000001f14d8      1220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn
  22    9  19d0 000000001bc666d0   1019220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
   9    c  13f4 000000001d173600   8008220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Completion Port)
  24   23  17c4 00000000001a0c40   1009220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  25   24  1088 000000001d205900   1009220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
   6   21  1248 000000001d1f6e80       220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn
   4   27   eb0 000000000019df08       220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn
  27   29   39c 000000001bc720f0   1009220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  28   26  17ec 00000000001a7be0   1019220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  29   2c  1040 000000001d1c8160   1009220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
   3   2a  1788 000000001d22ed48       220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn
  30   1f   830 000000001bc5b180       220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn
  32   1e   b38 000000001d1995a0   1009220 Enabled  0000000000000000:0000000000000000 001f0d80     2 Ukn (Threadpool Worker)
  33   1d  19fc 000000001d199a98   1019220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  34   1c   c84 000000000019f8a8   1009220 Enabled  0000000008d8d880:0000000008d8d88c 001f0d80     1 Ukn (Threadpool Worker)
  35   1a  12e8 000000001d1a1468   10092a2 Disabled 000000000c88e294:000000000c88e6d0 001f0d80     1 Ukn (Threadpool Worker)
   5   22  1a70 000000001d1a6008       220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn
  36   28  1050 000000001d209f18   1019220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  37   25  19f0 000000001d22f738   1019220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  38   2b  15cc 000000001d29b2d0      b220 Enabled  0000000000000000:0000000000000000 001f0d80     1 Ukn
  39   20  1228 000000001d290a88   1019220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  40   1b   c98 000000001d290420   10092a2 Disabled 0000000010adc094:0000000010addcf8 001f0d80     1 Ukn (Threadpool Worker)
  41   19  15dc 000000001d2a3168   1019220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn (Threadpool Worker)
  43   18  1a64 000000001d2c8cc0       220 Enabled  0000000000000000:0000000000000000 001b3b98     0 Ukn

据我了解，这很糟糕，基本上意味着在所有线程都启用此功能之前无法完成垃圾收集，这意味着进程处于挂起状态。

与帖子相比存在细微差异，这让我感到困惑，因为没有标有“（GC）”的线程 - 触发垃圾收集的线程？

但无论如何，由于两个线程设置为禁用，我认为这是问题所在，Tess 的挂起博客文章将继续告诉我确切的原因和解决方案。但不幸的是，它暗示了“mixed DLLloading problem”的问题，在查看了禁用线程的堆栈之后，两者都没有尝试加载 DLL。例如，这里是线程 40 的 kb：

1c93dc74 79142280 0ac30260 0bc85820 00000003 mscorlib_ni+0x29f318
1c93dc88 1e6a8c6c 1c93dc94 00000000 00000001 clr!OnHijackScalarTripThread
WARNING: Frame IP not in any known module. Following frames may be wrong.
1c93dca0 1e6791f7 00000003 00000000 00000000 0x1e6a8c6c
1c93e270 791421bb 0c886820 1bac554d 00000000 0x1e6791f7
1c93e284 7916a553 1c93e354 00000001 1c93e320 clr!CallDescrWorker+0x33
1c93e300 7916a6f4 1c93e354 00000001 1c93e320 clr!CallDescrWorkerWithHandler+0x8e
1c93e450 7916a729 1bd17090 1c93e574 1c93e720 clr!MethodDesc::CallDescr+0x194
1c93e46c 7916a749 1bd17090 1c93e574 1c93e720 clr!MethodDesc::CallTargetWorker+0x21
1c93e484 79190c04 1c93e720 ed47daf9 1c93ea18 clr!MethodDescCallSite::Call_RetArgSlot+0x1c
1c93e648 79190f53 1c85ce30 1bd17090 1b8b6834 clr!CallWithValueTypes_RetArgSlotWrapper+0x5c
1c93e930 79191115 1c85ce30 00000000 0c886b80 clr!InvokeImpl+0x621
1c93e9fc 79b3d839 1d1a1468 00000096 1c93ea18 clr!RuntimeMethodHandle::InvokeMethodFast+0x180
1c93ea50 79b3d52c 0ecc3e60 00000096 1038d084 mscorlib_ni+0x2bd839
1c93ea88 79b3c19d 00000000 00000000 0c885530 mscorlib_ni+0x2bd52c
1c93eab0 79ad6d16 00000000 0c885530 0ec452c4 mscorlib_ni+0x2bc19d
1c93ec04 7a045331 00000000 00000000 00000000 mscorlib_ni+0x256d16
1c93ecbc 672d72b5 0c862b08 00000000 00000000 mscorlib_ni+0x7c5331
1c93ece8 672eb90c 00000000 1c93ed18 0c862b08 System_Web_ni+0x1772b5
1c93ed28 67301e9e 1c93ed54 07f81050 0c863014 System_Web_ni+0x18b90c
1c93ed80 672b5998 1b8b2010 1b8e12c4 1c93f208 System_Web_ni+0x1a1e9e
1c93ed9c 67300602 0c862b08 0ec4af84 0c862b08 System_Web_ni+0x155998
1c93edd8 6730034d 0ac37a80 0c861c1c 1c93ee5c System_Web_ni+0x1a0602
1c93ede8 672ff8fd a65adfcd 79145c50 1c93effc System_Web_ni+0x1a034d
1c93ee5c 67935cdc 00000002 6726b530 00000000 System_Web_ni+0x19f8fd
1c93ee98 791425a1 1c93f228 00000002 028f2b9c System_Web_ni+0x7d5cdc
1c93eeac 79208c9b 67935cc0 6726b530 0ac4ea6c clr!COMToCLRDispatchHelper+0x28
1c93ef40 79208d74 6726b530 0ac4ea6c 00000001 clr!BaseWrapper<Stub *,FunctionBase<Stub *,&DoNothing<Stub *>,&StubRelease<Stub>,2>,0,&CompareDefault<Stub *>,2>::~BaseWrapper<Stub *,FunctionBase<Stub *,&DoNothing<Stub *>,&StubRelease<Stub>,2>,0,&CompareDefault<Stub *>,2>+0xfa
1c93ef64 79208dda 1d1a1468 1c93f1f8 1b7affe0 clr!COMToCLRWorkerBody+0xb4
1c93efbc 792098c9 1d1a1468 1c93f1f8 1b7affe0 clr!COMToCLRWorkerDebuggerWrapper+0x34
1c93f1cc 02b3a1aa 1d1a1468 1c93f1f8 a65adfcd clr!COMToCLRWorker+0x614
1c93f1e0 69f5aa4f 00000001 028038c8 00000000 0x2b3a1aa
1c93f544 69f5ab4a 028038c8 69f5aae2 1c93f56c webengine4!HttpCompletion::ProcessRequestInManagedCode+0x1cd
1c93f554 69f5aafe 028038c8 00000000 00000000 webengine4!HttpCompletion::ProcessCompletion+0x4a
1c93f56c 792078af 028038c8 ed47c90d 0000ffff webengine4!CorThreadPoolWorkitemCallback+0x1c
1c93f5bc 79206c5f 1c93f61f 1c93f61e ed47ca9d clr!UnManagedPerAppDomainTPCount::DispatchWorkItem+0x195
1c93f62c 792084c5 00000000 ed47ca25 00000000 clr!ThreadpoolMgr::NewWorkerThreadStart+0x20b
1c93f694 792f76e0 00000000 fff91c00 00000002 clr!ThreadpoolMgr::WorkerThreadStart+0x3d1
1c93ffb8 7d4dfb97 00247430 00000000 00000000 clr!Thread::intermediateThreadProc+0x4b
1c93ffec 00000000 792f7698 00247430 00000000 kernel32!BaseThreadStart+0x34

但后来我注意到了一些有趣的事情。通过使用!eestack -ee -short 命令，我看到线程 35 和 40（禁用 PreEmptive GC 的线程）都在同一个当前帧上：

Current frame: (MethodDesc 798ee360 +0xab System.Collections.Generic.Dictionary`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].FindEntry(Int32))

这就是我发帖this 的原因，让我觉得我肯定找到了问题所在。但不幸的是，在使用堆栈追溯代码后，有问题的字典不是静态的 - 所以我猜这不是问题。

我现在几乎没有想法 - 我不是分析转储文件的专家（事实上我昨天才开始 :D）所以如果有人对我接下来应该做什么以找出原因有任何指示这个问题会很好。

更新

运行Brian建议的~*ekb命令后，我找到了启动垃圾收集的线程，因为它在堆栈中有GarbageCollectGeneration。

1e61e54c 7d4d8c9e 000003c4 00000000 00000000 ntdll_7d600000!NtWaitForSingleObject+0x15
1e61e5bc 791897da 000003c4 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
1e61e5f0 7918981b 000003c4 ffffffff 00000000 clr!CLREvent::CreateManualEvent+0xf6
1e61e640 791896f1 00000000 efb5da31 0019f8a8 clr!CLREvent::CreateManualEvent+0x137
1e61e680 79189712 ffffffff 00000000 00000000 clr!CLREvent::WaitEx+0x126
1e61e694 792a05cc ffffffff 00000000 00000000 clr!CLREvent::Wait+0x19
1e61e6b8 792a04e5 ffffffff 00000000 0019f8f0 clr!SVR::gc_heap::wait_for_gc_done+0x6f
**1e61e6e0 792a424b 00000000 00000001 001bc600 clr!SVR::GCHeap::GarbageCollectGeneration+0x14f**
1e61e714 79229fd2 0019f8f0 00000040 00000000 clr!SVR::gc_heap::try_allocate_more_space+0x184
1e61e730 7922a080 0019f8f0 00000040 00000000 clr!SVR::gc_heap::allocate_more_space+0x30
1e61e750 79188f33 0019f8f0 00000040 00000000 clr!SVR::GCHeap::Alloc+0x55
1e61e76c 7915dd44 00000040 00000000 00000000 clr!Alloc+0x8d
1e61e7ac 7915dd84 0000001a 79169a39 79166166 clr!SlowAllocateString+0x42
1e61e7b4 79169a39 79166166 00000019 efb5d4c9 clr!UnframedAllocateString+0x12
1e61e7b8 79166166 00000019 efb5d4c9 00001f3e clr!StringObject::NewString+0x13
1e61e878 79ac139e 00000000 0019f8a8 0515fcd0 clr!COMNlsInfo::InternalChangeCaseString+0x128
1e61e88c 79ac51b4 0515fcd0 1e61e900 20e59f26 mscorlib_ni+0x24139e
1e61e898 20e59f26 1e61e900 08ce6208 050fd8e8 mscorlib_ni+0x2451b4

我还应该提到，我们的应用程序在 64 位服务器上以 32 位模式运行。不幸的是，当它最后没有响应时，我们忘记了 32 位的转储，这意味着当我们在 WinDbg 中加载转储文件时，我们需要运行!wow64exts.sw 命令来分析。不确定这有多大的不同（也许这就是为什么我看不到 '(GC)' 线程），但我们似乎无法让 `!clrstack' 命令工作。我们目前正在等待它再次无响应，以便我们可以在 32 位中进行转储。

【问题讨论】：

我觉得有趣的是没有一个线程被标记为正在执行 GC。您可以使用~*ekb 枚举调用堆栈，并查找与 GC 相关的方法来确定其中一个线程是否在收集中间。 @BrianRasmussen 根据我的更新，我发现线程正在执行 GC，但不确定如何从该命令中获取线程号？ 【参考方案1】：

所以我们最终找到了问题的根源。原来是我原来问题中提到的两篇文章的组合：

有两个线程试图访问同一个通用字典 GC 无法完成，因为两个线程已将 PreEmptive GC 设置为禁用。

更详细一点：

虽然两个线程处于某种死锁状态，但第三个线程加入了想要在堆上分配一些内存的一方。这会触发新的 GC，但 GC 无法完成，因为这两个线程的 PreEmptive GC 设置为禁用。由于 GC 无法完成，IIS 进程仍处于无法为请求生成新工作线程的状态，这意味着任何后续请求都将排队。队列继续增长，在应用程序池被回收之前不会返回任何响应。

正如我在最初的问题中提到的 - 我们将字典追溯到代码，它不是静态字典，所以我们假设这一定是红鲱鱼；两个线程怎么能访问同一个对象？事实证明这是可能的，因为字典存储在 InProc 会话中。

默认情况下，ASP.NET 会阻止对同一会话 ID 的并发请求。这是通过在每个请求的会话上放置一个排他锁来实现的，旨在防止这种确切的情况。然而，这是一个使用旧 AjaxPro 框架的“遗留”应用程序，并且已配置为绕过此锁定。这允许同一会话的并发 AjaxRequest 访问同一会话对象。

事实证明，我们最近在 javascript 中引入了一个错误，该错误会多次触发同一个 AjaxPro 请求，从而导致问题。

【讨论】：

【参考方案2】：

这可能完全超出了左侧字段，但在转储信息中，我注意到了这一点：

1c93eeac 79208c9b 67935cc0 6726b530 0ac4ea6c clr!COMToCLRDispatchHelper+0x28

COMToCLRDispatchHelper 调用让我想知道应用程序是否正在调用一个 32 位 COM 组件，这可能会让您有点摸不着头脑？

【讨论】：

我认为当从 IIS 调用 CLR 时，这是一个正常的调用堆栈，但是，就像你一样，我可能不在左侧字段中，因为我已经多年没有调试 IIS 转储了 :) 据我所知，我们的应用程序没有使用任何 COM 组件。我只是假设这与 IIS 调用我们的托管 CLR 应用程序有关......

以上是关于ASP.NET 挂起 - 通用字典并发问题导致 GC 死锁的主要内容，如果未能解决你的问题，请参考以下文章

ASP.NET 大量并发下载

ASP.NET 应用程序在调用后挂起

带有 ASP.NET Core 的 Visual Studio 2019 挂起（无响应）

每当使用异步时，ASP.Net MVC 4 控制器就会挂起

ASP.NET Core Web API 应用程序是不是可能出现死锁或应用程序挂起状态

对 Asp.Net App_Code 文件夹中的源代码进行更改时，Visual Studio 挂起