使用 PerfView 诊断 Windows 服务超时
4.80/5 (3投票s)
今天我想和大家分享一个我们系统中一个有趣的（希望如此）诊断案例。IngestService（就是它的名字）第一次启动时并不正常——它因为超过了默认的 30 秒超时而被终止。
今天我想和大家分享一个我们系统中一个有趣的（希望如此）诊断案例。IngestService（就是它的名字）第一次启动时并不正常——它因为超过了默认的 30 秒超时而被终止。但是第二次尝试总是成功的。没有抛出异常，也没有在事件日志中找到任何日志。这种情况 ETW 跟踪可能会有所帮助。由于这是一个 .NET 服务，我使用了 PerfView 来记录跟踪文件。诊断线程等待时间时一个重要的勾选框是 **Thread Time**（线程时间）框。
在生产环境中收集完跟踪后，我将它们合并并复制到我的开发机器上。
在跟踪中找到你自己
在 PerfView 中打开跟踪后，我通常首先检查 **TraceInfo**（跟踪信息）和 **Processes**（进程）视图。TraceInfo 视图将显示原始系统配置，而 Processes 视图列出了在收集跟踪时活动的进程。如果你的进程在整个跟踪会话期间都没有活动，那么记录在收集过程中启动或结束的进程是值得注意的。在我们的案例中，除了正在调查的 IngestService，我们还有 WmiAppSrv 和 dllhost 在会话期间启动。
深入了解
让我们通过打开跟踪的 **Thread Time Stacks**（线程时间堆栈）视图来开始我们的分析。
并选择 IngestService。对于线程时间分析，PerfView 会自动切换到 **CallTree**（调用树）选项卡，这可能是开始的最佳位置。现在，我们需要专注于我们调查的目标。您还记得该服务启动不正常（启动时间超过 30 秒），因此我们对进程的最后活动（特别是等待）感兴趣。通过检查时间范围列，我们可以看到进程中的所有线程直到其生命结束都生成了事件。
我们将时间分成两半，专注于后半部分（我们想知道最后一次等待是什么）。展开线程节点后，我们可以看到所有线程都处于 BLOCKED（阻塞）状态（当进程在结束时被终止时，它们有一些 CPU 时间，但这在我们这里不重要）。
我们需要回溯并专注于会话时间的前半部分。再次展开每个线程并检查其最后的 **CPU_TIME**（最后一次做事情的时间）。当有很多线程和很长的会话时间时，很难比较时间范围。因此，在这一点上，我通常会排除看起来不相关的线程，同时连续将时间范围分成两半，从秒到毫秒间隔进行。最终结果如下所示。
请注意，我们有一个 BROKEN stack（损坏的堆栈）节点，但根据 Last（最后）和 First（首次）时间戳和调用堆栈，我们可以很容易地猜测哪些等待是相关的。从截图中您可以看到，我们在这里等待某个 ALPC 连接。完整的堆栈如下（为了使代码更紧凑，我删减了一些帧）。
Name
...
| + MassTransit!ServiceBusFactory.New
| + MassTransit!ServiceBusConfiguratorImpl.CreateServiceBus
| + MassTransit!ServiceBusBuilderImpl.Build
| + MassTransit!ServiceBusBuilderImpl.CreateServiceBus
| + MassTransit!MassTransit.ServiceBus..ctor(class MassTransit.IEndpoint,class MassTransit.IEndpointCache,bool)
| + MassTransit!ServiceBus.InitializePerformanceCounters
| + MassTransit!MassTransit.Monitoring.ServiceBusInstancePerformanceCounters..ctor(class System.String)
| + clr!ThePreStub
...
| + MassTransit!MassTransit.Monitoring.ServiceBusPerformanceCounters..cctor()
| + MassTransit!MassTransit.Monitoring.ServiceBusPerformanceCounters..ctor()
| + MassTransit!ServiceBusPerformanceCounters.InitiatizeCategory
| + System.Core.ni![COLD] System.Linq.Enumerable.Count[System.__Canon](System.Collections.Generic.IEnumerable`1)
| + System.ni!PerformanceCounterCategory.CounterExists
| + System.ni!PerformanceCounterCategory.CounterExists
| + System.ni!PerformanceCounterLib.CounterExists
| + System.ni!PerformanceCounterLib.CounterExists
| + System.ni!PerformanceCounterLib.get_CategoryTable
| + System.ni!PerformanceCounterLib.GetPerformanceData
| + System.ni!PerformanceMonitor.GetData
| + mscorlib.ni!RegistryKey.GetValue
| + mscorlib.ni![COLD] Microsoft.Win32.RegistryKey.InternalGetValue(System.String, System.Object, Boolean, Boolean)
| + mscorlib.ni!DomainNeutralILStubClass.IL_STUB_PInvoke(Microsoft.Win32.SafeHandles.SafeRegistryHandle, System.String, Int32[], Int32 ByRef, Byte[], Int32 ByRef)
| + kernel32!RegQueryValueExW
| + kernel32!LocalBaseRegQueryValue
| + advapi32!PerfRegQueryValue
| + advapi32!QueryExtensibleData
| + advapi32!OpenExtObjectLibrary
| + WmiApRpl!WmiOpenPerfData
| |+ WmiApRpl!WmiAdapterWrapper::Open
| | + sechost!OpenServiceW
| | + sechost!QueryServiceStatus
| | + sechost!RQueryServiceStatus
| | + rpcrt4!NdrpSendReceive
| | + rpcrt4!NdrSendReceive
| | + rpcrt4!I_RpcSendReceive
| | + rpcrt4!LRPC_CCALL::SendReceive
| | + rpcrt4!LRPC_BASE_CCALL::SendReceive
| | + rpcrt4!LRPC_BASE_CCALL::DoSendReceive
| | + rpcrt4!LRPC_CASSOCIATION::AlpcSendWaitReceivePort
| | + ntdll!ZwAlpcSendWaitReceivePort
| | + ntdll!LdrInitializeThunk
| | + ntdll! ?? ::FNODOBFM::`string'
| | + ntdll!LdrpInitializeProcess
| | + wow64!Wow64LdrpInitialize
| | + wow64!RunCpuSimulation
| | + wow64cpu!ServiceNoTurbo
| | + wow64!Wow64SystemServiceEx
| | + wow64!whNtAlpcSendWaitReceivePort
| | + ntdll!ZwAlpcSendWaitReceivePort
| | + ntoskrnl!NtAlpcSendWaitReceivePort
| | + ntoskrnl!AlpcpProcessSynchronousRequest
| | + ntoskrnl!AlpcpReceiveSynchronousReply
| | + ntoskrnl!AlpcpSignalAndWait
| | + ntoskrnl!KeWaitForSingleObject
| | + ntoskrnl!KiCommitThreadWait
| | + ntoskrnl!KiSwapContext
| | + ntoskrnl!SwapContext_PatchXRstor
| | + BLOCKED_TIME
| | + CPU_TIME
查找原因
所以等待的根源在于 **MassTransit** 库，位于 ServiceBusPerformanceCounters 类的 InitiatizeCategory 方法中。让我们来看看。
// MassTransit.Monitoring.ServiceBusPerformanceCounters
private void InitiatizeCategory()
{
try
{
RuntimePerformanceCounter[] source = new RuntimePerformanceCounter[]
{
this.ConsumerThreadCount,
this.ReceiveThreadCount,
this.ReceiveRate,
this.PublishRate,
this.SendRate,
this.ReceiveCount,
this.PublishCount,
this.SentCount,
this.ConsumerDuration,
this.ConsumerDurationBase,
this.ReceiveDuration,
this.ReceiveDurationBase,
this.PublishDuration,
this.PublishDurationBase
};
if (!PerformanceCounterCategory.Exists("MassTransit"))
{
PerformanceCounterCategory.Create("MassTransit", "MassTransit Performance Counters", PerformanceCounterCategoryType.MultiInstance, new CounterCreationDataCollection((from x in source
select x).ToArray<CounterCreationData>()));
}
else
{
int num = (from counter in source
where !PerformanceCounterCategory.CounterExists(counter.Name, "MassTransit")
select counter).Count<RuntimePerformanceCounter>();
if (num > 0)
{
PerformanceCounterCategory.Delete("MassTransit");
PerformanceCounterCategory.Create("MassTransit", "MassTransit Performance Counters", PerformanceCounterCategoryType.MultiInstance, new CounterCreationDataCollection((from x in source
select x).ToArray<CounterCreationData>()));
}
}
}
catch (SecurityException)
{
string obj = "Unable to create performance counter category (Category: {0})\nTry running the program in the Administrator role to set these up." + ExtensionsToString.FormatWith("\n**Hey, this just means you aren't admin or don't have/want perf counter support**", new object[]
{
"MassTransit"
});
ServiceBusPerformanceCounters._log.Warn(obj);
}
}
我们可以看到它初始化了一些用于监控 MassTransit 客户端的性能计数器。但我们仍然不知道为什么该方法花费了这么长时间。但我们知道后台有一个 ALPC 连接。让我们在 PerfView 的 **Events**（事件）视图中查看在此时间范围内是否有任何 ALPC 跟踪。
所以有一个来自我们的 IngestService 的打开客户端连接（从未结束——找不到活动 ID 为 03b984af-47ba-4434-a6df-522edf9c1b42 的 RpcClientCall/Stop 事件）。我们还可以看到服务器端有一个 ALPC 连接（活动 ID：10b92075-ac49-4423-964d-c944a0f680a0），可能由我们的客户端连接触发，持续了 27 秒！当它结束时，IngestService 已经不再运行了。现在是时候分析 services.exe 进程在此期间在做什么了。让我们打开 **Thread Time (with ReadyThread)**（线程时间（带就绪线程））视图，选择 services (460) 进程，并将时间范围设置为 18,658.365 – 46,503.131。然后展开线程，找到那些几乎一直在阻塞的线程。我很快找到了一个线程 4004，它正在尝试启动一个服务，但需要等待某个临界区域。我还看到该线程被线程 4904 准备好，然后启动了一个新进程。
线程 4904 在此期间在做什么？
由 4004 线程启动的进程名称是什么？您可以向上滚动到帖子的开头，查看 **WmiApSrv** 进程的启动时间，您已经知道了答案。
现在，一切都清楚了。我们的 IngestService 在启动时请求了一些性能数据。为了提供这些数据，系统需要启动 WMI 性能适配器 (WmiApSrv) 服务。似乎在任何时候只有一个服务可以启动（除非它是依赖服务），并且有一个临界区域来确保这一点。最后，我们陷入了经典的死锁情况：IngestService 正在等待 WmiApSrv 收集一些性能数据，而 WmiApSrv 因为 IngestService 正在启动而无法启动。
解决方案
经过这次调查，解决方案很简单：我们将 WmiApSrv 添加为 IngestService 的一个依赖服务。
PerfView 问题
如果您在系统上不使用美国地区设置，那么在 PerfView 中选择日期范围很可能对您无效。我的地区设置是波兰语，我需要修改 PerfView 二进制文件才能在应用程序启动时设置不变的文化（我已经写信给 Vance Morrison 关于这个问题，但还没有收到答复）。如果您遇到此问题，请与我联系，我将帮助您。
