“ Explorer花了700毫秒打开任务栏的上下文菜单。 这一次的75％是从一个文件执行114,801次读取操作，平均读取数据量为68个字节。
我应该写一篇关于这个的文章还是讽刺的推文吗？”我在计算机上工作很快，因此当我必须等待应立即执行的操作完成时，这让我很烦。 我的重型家用笔记本电脑经常遇到的障碍是任务栏上的窗口关闭缓慢。 我右键单击该图标，等待菜单打开，然后选择“关闭窗口”。 在此过程中最慢的应该是鼠标移动，但是事实证明最长的部分是菜单出现之前的延迟。
这困扰了我很长一段时间，但我表现出反常的自我控制能力，使自己免受刺激。 直到今天，当我终于摔断并抓住
ETW示踪剂时。
这篇文章是作为快速博客的检查而写的。 从发现问题的那一刻起大约90分钟过去了，对此事进行了讽刺性的鸣叫 ，直到该帖子发表为止。
ETW跟踪器修复了如何右键单击任务栏并关闭两个资源管理器窗口的问题。 我使用具有默认选项的
UIforETW 跟踪到文件功能，导致
20.9 MB的诊断日志 。
有时，分析痕迹中最困难的部分是查找问题的位置，但是在这种情况下，这部分分析是微不足道的。 三个明确的信号指示正确的位置，是犯罪的罪魁祸首。
第一个信号是输入事件。 UIforETW包含一个集成的
输入记录器 （足够匿名，这样我就不会意外地窃取密码或个人信息），因此我只需要详细研究
MouseUp和
Button Type事件，其值2对应于鼠标右键。 同时，发生这些事件时，
WPA时间轴上会出现标记-请参见屏幕截图中的垂直线：
这使我清楚地知道，当我释放鼠标右键时，在600毫秒后，窗口焦点发生了变化，我认为这对应于菜单显示的那一刻。 此外，在释放鼠标按钮和更改窗口焦点之间，RuntimeBroker.exe具有明确的CPU活动块。
尚未证明窗口焦点的变化和CPU活动的相关性，但是使用屏幕记录应用程序进行测量时，我发现显示菜单大约需要660 ms，因此我倾向于相信这一点。
下一步是了解RuntimeBroker.exe在做什么。 尽管“
CPU使用率（精确度）”可以帮助您查看进程使用了多少CPU时间以及空闲原因，但是“
CPU使用率（采样）”表还是一个很好的工具，可以用来了解花费的CPU时间。 我仔细研究了一下，很快发现264个样本来自
KernelBase.dll！ReadFile ：
搜索更多之后，我发现其他调用堆栈也影响了此功能，因此我右键单击它，然后选择了
View Callers-> By Function 。 打开的模式（使用反向堆栈）显示，在此过程的899个样本中，有628个样本（占70％）来自通过此函数传递的不同调用堆栈：
该流中的271个样本未通过该功能，其余样本（未显示）在其他流中。
请注意，在10252的流中有899个采样代表两次鼠标单击，即每次鼠标单击大约450个采样或450毫秒（在1 kHz的标准采样频率下）。
有时文件I / O是CPU时间
CPU使用率（已采样）显示
CPU时间，因此此处通常不显示磁盘I / O，因为在这些时刻，流进入睡眠状态并等待磁盘。 I / O操作显示为CPU时间这一事实意味着所有读取都落在系统缓存上，而CPU时间是从缓存中获取数据所花费的额外内核资源（请参阅第一个采样调用堆栈中的
ntoskrnl.exe ）。
既然
文件I / O受到怀疑，我们需要转到
Graph Explorer-> Storage-> File I / O。 在稍微调整了列的外观之后，我们得到了以下令人印象深刻的结果：
, 10 252
RuntimeBroker.exe 229 604
ReadFile, 15 686 586 . 68 .
.
, — . ,
RuntimeBroker.exe . 4 027 904 , , , 1,9 .
, . , ( ):
%appdata%\Microsoft\Windows\Recent\AutomaticDestinations\f01b4d95cf55d32a.automaticDestinations-msWPA. — , . :
« „“, ( ) ( ) „“/ . , ».
, !
, . , , , .
- ReadFile, 68 . , , . , 4 , .
- , - , — .
- , - , . , ETW !
- https://aka.ms/AA60dfg
- , UIforETW ,
- , ( , ), shift+ . , .
- Hacker news
- Reddit
- Twitter