💒 ➗ 🔑 线性时间如何以O（n²）变为Windows ✴️ ☄️ 🌓

我最近在工作站上遇到了数分钟的延迟。经过调查，结果发现问题的原因是一个锁，该锁可能持续五分钟，在此期间，锁的来源基本上以九个指令的周期旋转。

对我来说，为帖子选择合适的标题非常重要，但是我立刻想起，不到一个月前写的一篇帖子已经用了适当的名称“九个指令阻止了48个内核”。被阻止的处理器的数量不同，周期更长一些，但是实际上，所有这些使您体验到deja vu。因此，当我解释发现的新问题时，我想反省一下为什么总是这样。

为什么会这样呢？

粗略地说，这些问题是由于观察到的结果而引起的，我将其称为道森的第一计算定律： O（n ² ）吸引了无法很好扩展的算法：它们足够快地投入生产，但又慢得足以破坏一切，当他们到达那里时。

O（n ² ）起作用-数据来自我的案例

这是怎么回事？开发人员编写代码并使用O（n ² ）算法。也许他没有意识到这一点，或者由于错误而使算法变为O（n ² ），或者开发人员知道他是O（n ² ），但是他认为这将不再重要。在实验室条件下，代码速度是可以接受的，并且对于现实世界中的大多数用户来说都是可以接受的，但是随后有人在启用App Verifier的情况下创建了7,000个进程，或者创建了包含18万个CFG元素的二进制文件，或者收集了如此大的DLL，扫描单链接列表，该列表占用了整个处理器。在研究Valve Source 2引擎的启动时间时，我发现了许多 O（n ² ）算法，每个算法都为引擎启动时间增加了约30秒，也就是说，这种问题在完全不同的开发人员中会发生。

O（n ² ）对于无法很好地扩展的算法具有吸引力：它们足够快才能投入生产，但足够慢就无法破坏一切。

没错

例如，对于每个正在运行的进程， App Verifier日志文件名的创建都是线性进行的，这是正常的，直到您意识到如果正在运行多个进程，这将导致O（n ² ）。有时甚至看不到嵌套的循环，或者形式上不是O（n ² ），或者循环能运行这么长时间以至于可以显着影响速度，这并不是显而易见的。

因此，请考虑这个机会，在编写代码时考虑一下，监视重负载下的性能扩展，并在分析重负载时检查可疑的代码段。或交给我，这样我就可以搜索它们并在我的博客上写文章。

让我们回到通常的抱怨中

和往常一样，我在拥有48个逻辑处理器和96 GB RAM的过时但功能强大的工作站上开展业务。我引入了忍者铬来制造Chromium，但是……什么也没发生。我看了一下，等待了二十秒钟，但组装从未开始。因此，我当然切换到UIforETW来记录ETW跟踪。更确切地说，我试图做到这一点。尝试开始跟踪记录时， UIforETW冻结 。在我的实践中，第一次有虫使用保护性措施阻止我探索它！

一两分钟后，Chromium的组装开始了， UIforETW开始了跟踪，但是开始太晚了，我对发生的事情一无所知。

具有选定的循环缓冲区跟踪的UIforETW选项

几天后，当同一件事发生时， UIforETW再次无法执行任何操作。这次，我将跟踪保留在循环内存缓冲区中工作，以准备第三次挂起。但是，这大大降低了我的构建工具的速度，因此几个小时后我放弃了。

然后，这种情况再次重演。这次我运行了Microsoft创建的ETW跟踪日志记录工具-wprui ，并且能够开始记录。大约40秒后，装配开始工作，我得到了跟踪！

我现在可以开始调查吗？

之前，我在“任务管理器”中注意到WinMgmt.exe在这些冻结期间正在运行。在查看了WPA中的CPU使用率（精确）数据之后，我确信在40秒钟以上的时间内， WinMgmt.exe几乎是唯一的工作过程，在WinMgmt.exe关闭后，我的机器开始工作了：

WinMgmt.exe完成后，我们等待进程的唤醒

所有这些都是相当可疑的，但是我明智的读者知道，“之后”并不意味着“由于”，而需要证明。

像上次一样，我估算了图表上的解锁时刻，并按“切入时间”对上下文开关进行了排序，并查找了“自上次以来的时间很长”值（指示未执行线程的时间长度）的第一个开关。错过了十几个只是短暂停机时间的线程，我发现等待了41.57秒的许多线程中的第一个。睡眠线程没有唤醒WinMgmt.exe ，但是我很快发现它被唤醒WinMgmt.exe的线程唤醒了不到一毫秒。

有关CPU使用率（精确）图和准备线程/新线程概念的说明，请参见本教程或本文档。

在具有内容切换数据的屏幕快照中，第17行包含流72,748（WinMgmt.exe） ，该流将激活流74,156（svchost.exe）。 接下来，在第19行上，线程74,156（svchost.exe）激活了等待时间为41.57秒的线程58,704（svchost.exe） 。这是长时间睡眠后唤醒的第一个线程，并由此继续激活流。可以在“ 新建线程ID”列中看到刚刚被激活的线程，然后往下走几行，在“ 就绪线程ID”列中看到它们，从而激活另一个线程。名称和进程ID可帮助您了解上下文。第17行与第18行和第19行相关联，第19行与第20行相关联，第20行与第23行相关联，第23行与第27行相关联，依此类推；每个线程由链中的前一个线程激活：

怪物醒来-长时间闲置的线程栩栩如生

41.57阻塞线程的时间很长，但实际上阻塞了数百个线程，而且阻塞时间更长。它们的“自上一次以来的时间”值约为41.5秒的唯一原因是因为解析了挂起之前的跟踪长度。

似乎结果与WinMgmt.exe中存在问题的理论相符，但是他们没有证明这一点。当我在“ 跟踪”->“系统配置”->“服务”中查看svchost.exe（3024）并发现它是Winmgmt服务时，我的信心增强了，但是我仍然需要更多的确定性。

经过一番翻番（在时间上前后移动），我认为交互太复杂了，无法详细分析它们，尤其是没有流名称可以向我们提示svchost.exe（3024）中25个不同线程在做什么。

证明！

然后，我决定以其他方式处理WinMgmt.exe有罪证明。也许值得一开始，但这太简单了。我从WPA的“ 进程”表中获取了命令行WinMgmt.exe ，并手动启动了它。该命令具有以下形式：

winmgmt.exe / verifyrepository

大约花了五分钟当它起作用时（我花了很多时间），我发现无法从UIforETW启动ETW跟踪。这样的证据比我能做的任何复杂分析都要好。

配置仅显示长休眠线程

然后，我再次运行repro，并且跟踪已在运行；在分析了跟踪之后，我发现了一百多个进程的线程被阻塞超过五分钟！

再说一遍...

出于习惯，我再次查看了CPU使用率（采样）数据，以查看WinMgmt.exe在浪费时间。我很快发现96.5％的示例位于repdrvfs.dll！CPageCache :: Read（）中 ，在四个不同的堆栈上调用：

导致我进入CPageCache的四个路径::阅读

这里显示了此功能的完整堆栈树，主要针对希望研究此问题的Microsoft人士：

导致CPageCache的完整堆栈::以三种方式读取

我添加了一个地址列，发现95.3％的示例处于9条指令的一个周期中（示例总是只有9条指令中的7条下降（如果您想知道为什么，请参阅此处），但是调试器显示了整个周期的大小）：

按地址抽样-七个非常“热门”的地址

然后，我手动启动winmgmt.exe / verifyrepository ，并同时收集有关正在执行的分支指令的CPU计数器数据。由此，我可以粗略计算出循环运行了多少次。这可能不是必需的，但是我想确保循环执行了很多次，并且执行不慢（出于某种原因）。我认为我可以简单地做到这一点很酷，只需对批处理文件进行一些微小的更改即可。我发现WinMgmt.exe每个周期执行大约一条分支指令，也就是说，该周期（据我所知，消耗了大部分CPU时间）非常快，而速度下降是由于它运行了数亿个事实次。

Xperf延迟

只是出于细致的考虑，我决定看看为什么UIforETW在此事件期间无法开始跟踪。原来， UIforETW正在运行xperf ，但是在此调用堆栈中， xperf空闲了41.5秒（实际上更长）：

xperf.exe！wmain
xperf.exe！CStopTrace ::执行
perfctrl.dll！LoggingSession :: EnumLoggers
perfctrl.dll！LoggingSession :: LoggingSession
perfctrl.dll！LoggingSession :: CreateProviderList
perfctrl.dll！GetProviderInfoCache
perfctrl.dll！CProviderInfoCache :: CProviderInfoCache
tdh.dll！TdhfEnumerateProviders
tdh.dll！TdhpWbemConnect
wbemprox.dll！定位器:: ConnectServer
wbemprox.dll！CDCOMTrans :: DoActualConnection

简而言之， xperf由Wbem调用，因此受到此问题的阻止。 xperf尝试在启动跟踪之前停止跟踪，因为我添加了此行为，以使跟踪的启动更具容错性。我怀疑仍然会发生绞死，但我不确定。

我们创建计算复杂度的图表

我注意到WinMgmt.exe扫描了c：\ windows \ System32 \ wbem \ Repository目录 ，该目录在我的计算机上为1.9 GB，因此我在工作中和Twitter上询问该目录获取数据点所需的空间。我还要求人们修复winmgmt.exe / verifyrepository的运行时，并开始计划。即使这些测试是在完全不同的计算机上以不同的CPU速度进行的，该图也非常清楚：

时间的平方根与存储库大小之间的关系

这张sqrt（时间）与存储库大小之比的图表对于从六台不同机器接收的数据而言是理想的，尽管如此，它还是真实的。显然， VerifyRepository函数具有O（n ² ）性能。如果n是存储库目录的大小（以GB为单位），则VerifyRepository大约需要1.6 * n ²分钟。对于所有值（从一秒钟到十分钟），这都是一个不错的粗略估计。

总结

winmgmt.exe / verifyrepository包含9条指令的周期，其执行的迭代次数与wbem存储库大小的平方成正比。因此，命令的执行最多可能需要十分钟，尽管实际上它只需几秒钟即可执行。这本身就是不好的。

但更糟糕的是，该团队在其操作期间执行了WMI（ Windows管理规范）锁定，因此执行WMI操作的任何进程都将冻结。

惊人的谜语

每小时运行一次winmgmt.exe / verifyrepository的脚本已经这样做了很多年，但是有问题的行为只是在一两个月前才开始出现。据推测，这意味着wbem存储库最近变得更大了。 0.5 GB的延迟很容易被忽略，但是从1.0 GB及更高的延迟已经可以缓解。正如在Twitter上建议的那样，我为objects.data文件运行了strings.exe 。许多最常见的字符串名称中都包含polmkr，但是我不知道这意味着什么。

我在Twitter上发布了一个错误报告，起初它引起WMI团队的某些动议，但后来我停止接收答案，所以我不知道现在的情况。

我希望看到针对性能问题的修复程序，并且希望我们的IT部门能够找到并解决导致wbem存储库如此之大的问题。但是目前，IT部门已承诺不再每小时运行一次/ verifyrepository命令，这应该有助于我们避免最严重的症状。

参考文献

可在此处获得ETW教程，研究和文档的常规列表： https : //tinyurl.com/etwcentral
CPU使用率（已采样）教程（用于了解花费的CPU时间）在此处，文档在此处。
CPU使用率（精确）教程（用于查找无法运行线程的原因）在此处，文档在此处。
文章正文中提供了指向各个文章的链接，您也可以在我的调查报告类别中找到它们。
关于O（n ² ）算法的其他故事可以在偶然的平方中阅读

关于Reddit的文章的讨论在这里，关于黑客新闻的讨论在这里，在Twitter上的话题在这里，可能在这里

线性时间如何以O（n²）变为Windows