xperf WinDBG C# .NET 4.5.2 应用程序 - 了解进程转储
Posted
技术标签:
【中文标题】xperf WinDBG C# .NET 4.5.2 应用程序 - 了解进程转储【英文标题】：xperf WinDBG C# .NET 4.5.2 Application - Understanding process dump 【发布时间】：2015-12-25 19:31:22 【问题描述】：在重负载下，我们的应用程序正在使强大的服务器达到 100% 的 CPU 使用率。阅读进程转储，查看线程，其中一些是 10 分钟。在使用 !CLRStack 时，它们都没有给我任何见解。
!runaway 给了我：
0:030> !runaway
User Mode Time
Thread Time
53:2e804 0 days 0:10:04.703
30:31894 0 days 0:07:51.593
33:47100 0 days 0:07:24.890
42:11e54 0 days 0:06:45.875
35:35e18 0 days 0:06:07.578
41:54464 0 days 0:05:49.796
47:57700 0 days 0:05:45.000
44:3c2d4 0 days 0:05:44.265
32:3898c 0 days 0:05:43.593
50:54894 0 days 0:05:41.968
51:5bc58 0 days 0:05:40.921
43:14af4 0 days 0:05:40.734
48:35074 0 days 0:05:40.406
...
在其中一个线程上调用 !DumpStack，我得到：
0000001ab442f900 00007ff9ef4c1148 KERNELBASE!WaitForSingleObjectEx+0x94, calling ntdll!NtWaitForSingleObject
0000001ab442f980 00007ff9e920beb2 clr!SVR::gc_heap::compute_new_dynamic_data+0x17b, calling clr!SVR::gc_heap::desired_new_allocation
0000001ab442f9a0 00007ff9e90591eb clr!CLREventWaitHelper2+0x38, calling kernel32!WaitForSingleObjectEx
0000001ab442f9b0 00007ff9e90e0d2c clr!WriteBarrierManager::UpdateEphemeralBounds+0x1c, calling clr!WriteBarrierManager::NeedDifferentWriteBarrier
0000001ab442f9e0 00007ff9e9059197 clr!CLREventWaitHelper+0x1f, calling clr!CLREventWaitHelper2
0000001ab442fa40 00007ff9e9059120 clr!CLREventBase::WaitEx+0x70, calling clr!CLREventWaitHelper
0000001ab442fa70 00007ff9ef4c149c KERNELBASE!SetEvent+0xc, calling ntdll!NtSetEvent
0000001ab442faa0 00007ff9e90ef1e1 clr!SVR::gc_heap::set_gc_done+0x22, calling clr!CLREventBase::Set
0000001ab442fad0 00007ff9e90e9331 clr!SVR::gc_heap::gc_thread_function+0x8a, calling clr!CLREventBase::WaitEx
0000001ab442fb00 00007ff9e92048e7 clr!SVR::gc_heap::gc_thread_stub+0x7a, calling clr!SVR::gc_heap::gc_thread_function
0000001ab442fb60 00007ff9e91a0318 clr!Thread::CLRSetThreadStackGuarantee+0x48, calling kernel32!SetThreadStackGuaranteeStub
0000001ab442fb90 00007ff9e91a01ef clr!Thread::CommitThreadStack+0x10, calling clr!Thread::CLRSetThreadStackGuarantee
0000001ab442fbd0 00007ff9e910df0b clr!ClrFlsSetValue+0x57, calling kernel32!SetLastErrorStub
0000001ab442fc00 00007ff9e92048dc clr!SVR::gc_heap::gc_thread_stub+0x6f, calling clr!_chkstk
0000001ab442fc40 00007ff9f0d316ad kernel32!BaseThreadInitThunk+0xd
0000001ab442fc70 00007ff9f1e54409 ntdll!RtlUserThreadStart+0x1d
它告诉我什么？我看到很多对 CLR 的调用，但我不明白问题出在哪里。在 .reload（Thomas 建议）之后，现在我可以看到 GC 调用了。
更新 1
运行 xperf 后，每个 w3wp.exe 消耗大约 45% 的 CPU。按其中一个过滤并按功能分组，有一个功能标记为“？”占 13.62%，其他为 2.67% 或更少。我怎么知道这是什么“？”？
更新 2
再次运行 xperf，函数 JIT_MonEnterWorker_InlineGetThread_GetThread_PatchLabel 负责 12.31% 的 CPU 使用率。这 ”？”功能仍然存在。
按堆栈分组：
Line #, Stack, Count, Weight (in view), TimeStamp, % Weight
2, |- ?!?, 501191, 501222.365294, , 35.51
3, | |- clr.dll!JITutil_MonContention, 215749, 215752.552227, , 15.28
4, | |- clr.dll!JIT_MonEnterWorker_InlineGetThread_GetThread_PatchLabel, 170804, 170777.100191, , 12.10
如您所见，这两个占 CPU 使用率的 27% 以上（对于每个进程，这很重要）。
更新 3
使用 wpr.exe 后（@magicandre1981 建议）：
wpr.exe -start cpu and wpr -stop result.etl
我发现 FormsAuthentication 和一些在关键路径上对 Ninject 的不必要调用导致了大约 16% 的 CPU 使用率。我仍然不明白运行 gor 10 分钟或更长时间的线程。
更新 4
尝试了 DebugDiag（来自@leppie 的建议），它刚刚确认挂起的线程都类似于：
Thread ID: 53 Total CPU Time: 00:09:11.406 Entry Point for Thread: clr!Thread::intermediateThreadProc
Thread ID: 35 Total CPU Time: 00:07:26.046 Entry Point for Thread: clr!SVR::gc_heap::gc_thread_stub
Thread ID: 50 Total CPU Time: 00:07:01.515 Entry Point for Thread: clr!SVR::gc_heap::gc_thread_stub
Thread ID: 29 Total CPU Time: 00:06:02.264 Entry Point for Thread: clr!SVR::gc_heap::gc_thread_stub
Thread ID: 31 Total CPU Time: 00:06:41.281 Entry Point for Thread: clr!SVR::gc_heap::gc_thread_stub
或由于 StackExchange.Redis：
DomainBoundILStubClass.IL_STUB_PInvoke(Int32, IntPtr[], IntPtr[], IntPtr[], TimeValue ByRef)+e1
[[InlinedCallFrame] (StackExchange.Redis.SocketManager.select)] StackExchange.Redis.SocketManager.select(Int32, IntPtr[], IntPtr[], IntPtr[], TimeValueByRef)
StackExchange.Redis.SocketManager.ReadImpl()+889
StackExchange.Redis.SocketManager.Read()+66
或
[[GCFrame]]
[[HelperMethodFrame_1OBJ] (System.Threading.Monitor.ObjWait)] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
mscorlib_ni!System.Threading.Monitor.Wait(System.Object, Int32)+19
StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[[System.__Canon, mscorlib]](StackExchange.Redis.Message, StackExchange.Redis.ResultProcessor`1, StackExchange.Redis.ServerEndPoint)+24f
StackExchange.Redis.RedisBase.ExecuteSync[[System.__Canon, mscorlib]](StackExchange.Redis.Message, StackExchange.Redis.ResultProcessor`1, StackExchange.Redis.ServerEndPoint)+77
[[StubHelperFrame]]
StackExchange.Redis.RedisDatabase.SetMembers(StackExchange.Redis.RedisKey, StackExchange.Redis.CommandFlags)+ee
【问题讨论】：
在WaitForSingleObjectEx() 中等待的东西不会消耗CPU，因为它正在等待并且没有工作。死锁中的线程也不会消耗 CPU，因为它们都在等待资源。
使用 ETW/xperf/WPA 跟踪 CPU 使用情况：channel9.msdn.com/Shows/Defrag-Tools/…
分析您的 GC 数据：channel9.msdn.com/Shows/Defrag-Tools/…、channel9.msdn.com/Shows/Defrag-Tools/…、channel9.msdn.com/Shows/Defrag-Tools/…、channel9.msdn.com/Shows/Defrag-Tools/…
如果可以，您应该在这种情况下进行分析，而不是分析内存转储。 ***.com/questions/3927/…
我的 2 美分，使用 DebugDiag 来检查锁。
【参考方案1】：
手动操作需要勇气 ;) 请查看官方 MS DebugDiag 2.2：https://www.microsoft.com/en-us/download/details.aspx?id=49924 它带有 analyzer，因此您不必使用你的手。使用 DebugDiag，我认为您会比以往更快地发现问题...
【讨论】：
【参考方案2】：缓慢的应用程序，可能来自缓慢的代码，也可能来自 .NET 引擎
首先，如果您检查了 clr.dll，如果它有问题，您可以下载它并在您的计算机上替换它 否则，如果它没有任何问题试试这个
我认为您应该检查您的应用程序代码，并仔细检查需要大量进程的每个角落，并尝试平衡 CPU 和 RAM 之间的代码操作负载。 循环，对象初始化或递归函数等。 一切都会增加 CPU 负载尝试将分片对象存储在 static 或 Constant
【讨论】：
第二段看不懂。阅读这么大的应用程序的整个代码并不容易，但是（是的）有时它可能是唯一的选择（至少是经常被命中的部分）。关于使用静态共享对象，如果数据失效，则在所有实例上更新它时会出现问题（可以解决，但事实并非如此） 我会尽力帮忙吗:) 也许我很难抓住这个案子以上是关于xperf WinDBG C# .NET 4.5.2 应用程序 - 了解进程转储的主要内容，如果未能解决你的问题，请参考以下文章