凌晨 3:00 出了什么问题？

引言

我回到韩国，调查客户计算机系统可能存在的问题，并探索性能监视器的跟踪和日志功能如何协同工作，以确定系统出现问题时内部发生的情况，以及哪些程序可能造成瓶颈。这是一个 Windows 系统，但您可以在大多数 Unix 系统上找到类似的工具，即系统分析报告 (sar) 工具。

首先介绍一下。如果您不熟悉性能监视器，请按住 Windows 键和 'R'，输入“perfmon”（不带引号），然后单击“确定”按钮。您的第一印象可能会是它看起来与 Windows 任务管理器（按 Ctrl-Alt-Delete 时运行的那个程序）上的图形相同，而且您不会错得太离谱。默认计数器是**每秒页数 (Pages/sec)**、**平均磁盘队列长度 (Avg. Disk Queue Length)** 和**处理器时间百分比 (% Processor Time)**，显示的值是短时间周期（一分四十秒）内的当前活动。但是，使用性能监视器，您可以配置数千种不同的计数器进行监视；您可以将图形记录到磁盘，格式为紧凑的二进制格式、更易于传输的文本格式，甚至可以将数据记录到 SQL Server 数据库；您可以设置记录的开始和停止时间表；等等。一旦您开始使用性能监视器，它就会比您在任务管理器中看到的图形强大得多。

使用的系统性能工具

性能监视器

性能监视器（或 perfmon）是 Microsoft Windows 基于的工具，用于收集性能计数器数据并以图形方式显示。有一个命令行界面，称为 LogMan，允许您创建和控制性能监视器日志，但主要用于管理脚本。

系统分析报告

系统分析报告（或 sar）是用于在 Unix 基于的系统上收集性能日志的工具。虽然本文不会使用它，但为了完整性而提及。

性能日志更适合观察资源的长期消耗增长，以便预测未来需求，但它们也可非常有效地用于疑难解答复杂的系统问题。理想情况下，它们会提供更多用于疑难解答的选项，但它们本身已经非常有效，并且您可以随时创建自定义工具以其他方式分析原始数据。

不过，现在，让我们熟悉一下如何使用该工具以及一些报告有关系统疑难解答的有趣数据的计数器。打开性能监视器后，单击计数器并删除它们。接下来，在同一区域内右键单击并选择“添加计数器”。我们将添加的计数器及其说明如下。

当您右键单击并选择“添加计数器…”时，您将看到“添加计数器”对话框。前两个单选按钮无关紧要，因为它们可能指的是同一台计算机，所以暂时忽略它们。“性能对象”下拉列表是您正在查看的类别或计算机子系统的选择。如果您知道哪个子系统可能导致问题，您可以从该子系统选择更多计数器，但计算机通常会给您带来惊喜。因此，在本讨论中，我将从各种子系统中选择大约十几个计数器，以便找到可能显示意外行为的子系统。在下面的计数器列表中，冒号前的名称将是您应该在其中找到该计数器的类别。

内存：% 已提交字节使用量

这是您的计算机为运行任务分配的字节百分比。这个数字越高，系统为执行任务的内存就越少。

内存：每秒页读取次数

这指的是系统在虚拟内存系统上需要执行的读取次数。任何时候启动新应用程序，您都会期望它从页面文件中读取以分配新内存。然而，在使用单个或少量应用程序期间的大量读取强烈表明系统需要更多内存才能高效运行。

网络接口：每秒接收字节数

这显示了通过网络接收的字节数。它并不能真正有效地指示问题，但如果我们看到它长时间运行接近满负荷，我们可以进一步调查。现在，我们只是在寻找异常活动。

网络接口：每秒发送字节数

这显示了通过网络发送的字节数。它与上面的计数器类似，但用于发送信息而不是接收信息。

物理磁盘：% 磁盘时间

这是处理器用于管理磁盘数据的时间百分比。这是用于读取和写入的总时间。分隔的数据更有助于理解正在发生的事情，但总数有助于告诉您访问磁盘付出了多少努力。

物理磁盘：% 磁盘读取时间

这是处理器用于从磁盘读取的时间百分比。它与上面的计数器类似，但它告诉您磁盘是正在被读取（而不是写入）。

物理磁盘：% 磁盘写入时间

这是处理器用于写入磁盘的时间百分比。它与前两个计数器类似，但仅限于写入磁盘的时间。

处理器：% 处理器时间

这显示了处理器正在处理的时间量（而不是空闲）。

处理器：每秒中断次数

这个计数器本身用处不大。它显示了处理器正在接收多少请求。中断通常由连接到系统的设备（磁盘、网卡等）引发，以请求高优先级 CPU 时间。我们在这里包含它以便与下一个计数器进行比较。

系统：每秒系统调用次数

这是 CPU 每秒服务的系统调用次数。通过比较每秒处理器中断次数与每秒系统调用次数，我们可以了解系统响应连接的硬件需要多少努力。在一个健康的系统中，每秒中断次数与每秒系统调用次数相比应该可以忽略不计。当系统必须反复调用中断进行服务时，这表明硬件故障。如果我们看到这种情况，我们将添加更多计数器来查找特定的硬件故障，但现在，我们正在广泛搜寻异常情况。

TCP 计数器

我们将要添加的下一个两个计数器 — **TCP：每秒重传的段数 (TCP: Segments Retransmitted/sec)** 和 **TCP：每秒发送的段数 (TCP: Segments Sent/sec)** — 需要更详细的解释。由于这两个计数器不像其他计数器那样通用，因此我觉得有必要对其进行解释。我正在进行疑难解答的计算机是一台专用计算机，用于运行一组特定的应用程序来控制钢铁制造，作为自动化控制系统的一部分。此应用程序的一个重要部分是网络通信。绝大多数网络流量是 TCP，而不是 UDP 或其他 IP 协议。但是，您不应将这些计数器误认为是对网络流量的完整描述，尤其是一些过程自动化应用程序大量使用 UDP 并可能产生巨量流量。此外，这些计数器仅测量此机器的统计信息，而不是网络上的总体流量。因此，我们将重传率视为网络拥塞的可能间接指标。

如果您听过一半的电话对话，您会注意到（幽默地）对话中会有一些部分，例如：“嗯哼。”“是的。”“哦。”“嗯。”“是的。”“啊哈。”“嗯。”在 TCP/IP 网络中，这些称为确认或 ACK。当在一定时间内没有收到确认时，您可能会听到“你还在吗？”或“喂？”在 TCP 中，这称为重传超时。您不知道对话为什么停止 — 它就是停止了。对话停止的一个可能原因是太多其他人也在尝试打电话，网络过载，您的对话被打断了。当然，对话停止的原因还有很多，从注意力不集中到穿过隧道（这里经常发生）。根据对话的长度（以及您对主题的兴趣），预计会有一定程度的重传。然而，当给定对话的重传率增加时（现在能听到我说话吗？），这表明存在网络中断（或者只是该换个话题了）。

同样，如果您的网络工作良好，发送的段数与重传数的比率应该很低 — 低于 4%。如果高于此值，您应该更仔细地检查您的网络。通过包含这两个计数器，我主要寻找可能导致客户遇到的周期性中断的突发中断。如果我们需要更仔细地检查网络流量，我们将不得不获取像 Wireshark、MRTG 或 Nagios 这样的独立工具。现在，我们只寻找可能的感兴趣的领域，而不是原因，这两个就足够了。

记录计数器

一旦您熟悉了图形，这些设置就必须持久化，而且我恐怕无法轻松地将计数器从实时图形传输到可记录的事件日志定义，所以我们将不得不重新设置它们。打开 Perfmon 后，您应该在左侧看到一个树状结构，其中有一个名为“性能日志和警报”的节点。展开该节点，您应该会看到一个名为“计数器日志”的节点。选择此节点应将右侧的图形更改为性能事件日志定义列表。默认情况下，Windows 附带一个名为“系统概述”的示例事件日志。右键单击右侧面板上的空白区域，然后选择“新建日志设置…”我们将此命名为“基线”，因此将其输入文本框并单击“确定”按钮。“事件日志设置”对话框将打开到“常规”选项卡。在这里，您将浏览上面列出的计数器列表并添加它们。接下来，单击“计划”选项卡，然后在“启动日志组”中选择“手动启动”单选按钮。单击对话框的“确定”按钮以关闭并保存您的设置。从这里，您可以右键单击事件日志，以便在方便时开始记录。一天记录会创建一个约 3MB 的文件，并（默认）存储在 `C:\perfmon\` 目录中，扩展名为 BLG。我无法想象磁盘空间会成为问题，但您应该注意磁盘使用情况，并至少准备好尽快传输这些日志文件。理想情况下，您会将所有事件日志（更重要的是，跟踪日志）记录到外部驱动器或扩展分区。

事件日志开始记录后，您可以关闭 perfmon 并像往常一样使用您的系统，浑然不知它正在记录。完成后，再次打开 perfmon，浏览回事件日志，右键单击它并选择停止。一旦创建了日志，您就可以在任何计算机上的 perfmon 中打开该文件。从图形屏幕（选择了“系统监视器”节点），您会看到图形上方有一个工具栏，上面有一个看起来像汽水罐的图标。这是数据的一个通用符号。该图标被设计成看起来像一个旧的磁性内存鼓 — 硬盘驱动器​​的前身 — 它曾经有膝盖那么高，宽度足够坐着，但只能提供一兆字节或更少的存储。这些鼓是所有长期存储的来源，并迅速成为数据存储和检索的象征。

查看结果

当“系统监视器属性”对话框打开且“源”选项卡被选中时，单击“日志文件”单选按钮，单击（现在已启用的）“添加”按钮，然后浏览到您的事件日志文件。选择您的日志文件，单击“应用”，然后切换到“数据”选项卡。在这里，删除任何定义的计数器，然后单击“添加”按钮并选择“所有计数器”单选按钮。当您逐一浏览每个“性能对象”时，此设置将保持不变，所有您记录的计数器都将列出。因此，请浏览下拉列表中的每个“性能对象”并单击“添加”按钮。完成后，单击“添加计数器”对话框的“关闭”按钮，然后单击“系统监视器属性”对话框的“确定”按钮，将显示带有所有计数器的图形。这是我正在进行疑难解答的计算机上的图形图像。

在图形上方的工具栏中，您可以单击黄色的灯泡来切换突出显示。然后，在图形下方，当您逐一选择每个计数器时，它将突出显示图形中相应的线条。突出显示使我能够快速识别上面的下降和尖峰，即**处理器时间**和**已发送的段数**的下降，以及**每秒页数**和**磁盘时间百分比**的异常尖峰。尖峰几乎肯定是由我们的监视程序引起的，该程序会终止并重新启动未响应看门狗超时的任务。了解系统的一部分有助于快速隔离感兴趣的行为变化。

了解系统

我们有一个任务，其唯一职责是定期向其他每个任务发送内部进程通信 (IPC) 消息并请求响应。如果任何其他任务在合理的时间内未响应，监视任务将尝试终止并重新启动该任务。当新任务加载时，由于操作系统在页面文件中分配空间来运行应用程序，因此会出现磁盘访问激增。简而言之，**磁盘时间百分比**和**每秒页数**的尖峰是对问题的正常响应，而不是问题的根源。**已发送的段数**的下降清楚地表明我们的程序已停止在网络上通信，而**处理器时间**的下降则证实了我们的程序正在失败，但这些都不能真正说明原因。

我们的程序确实维护着一个正在发生的事件的运行日志，因此下一步是确定性能下降发生的时间范围，看看我们是否能在日志文件中找到任何东西。右键单击图形并选择“属性”。在“系统监视器属性”对话框中，单击“源”选项卡，然后将对话框拖开，使其保持可见但不会遮挡后面的图形。在对话框的“确定”按钮和“取消”按钮的正上方，您将看到“时间范围滑块”。您可以独立地左右拖动滑块来调整时间段的开始和结束时间。当您调整这些滑块时，您会看到一条暗灰色条在图形上移动，以帮助将时间与图形趋势（如我们的下降）对齐。当我将下降夹在中间时，我注意到它开始时间非常接近午夜，结束时间非常接近凌晨 1 点。

午夜是自动化活动的流行时间：首先因为它标志着一天的结束，其次因为它通常被认为是活动减少的时间，非常适合由备份脚本引起的中断。当然，如果这是一项自动化任务，这种行为将每晚在同一时间重复。因此，除了查看日志文件以查找可能在午夜前发生的任何异常情况外，我还想记录夜间日志以验证这是一种趋势，而不是单一事件。

查看日志文件并未发现午夜有什么明显的问题。相反，午夜的活动奇怪地缺席，考虑到至少应该有监视任务不得不终止并重新启动无响应任务的记录。然而，第二天和第三天的重复日志确实显示这是一种日常发生的情况，总是在午夜。尽管我们的软件确实会在每天结束时打开一个新的日志文件，但它不会在午夜进行任何日常计算来报告；然而，计算机上运行着其他软件，并且可能有一些其他应用程序正在接管机器来进行计算。在这种情况下，我本来会期望看到页面数每秒的尖峰，因为一个新的线程或派生应用程序启动了。此外，我本应在审查每日活动记录的期间看到磁盘访问量增加。然而，这些副作用完全有可能被停止运行在这里的程序的意外副作用所掩盖。唯一能确定的是，需要更仔细地查看此时可能启动的应用程序和线程。

记录事件

由于我们的服务减少总是在午夜发生，我们将开始记录从午夜前到午夜后执行的所有任务的启动和停止。要执行此记录，我们将使用 perfmon 中的跟踪日志。打开性能监视器后，在左侧窗格中展开“性能日志和警报”节点，然后选择“跟踪日志”。在右侧窗格中，右键单击屏幕的空白部分，然后选择“新建日志设置”。我们将此跟踪日志命名为“皮卡丘”。我不是特别喜欢这个角色或动画，但忍不住用了这个双关语；然而，如果这太幼稚了，您可以随意命名，只要在给出名称后单击“确定”按钮即可。现在，我们将记录来自默认系统提供程序的事件，因此请选中“系统提供程序记录的事件”单选按钮。我们不关心磁盘 I/O 或 TCP/IP，因此请取消选中它们以帮助减小此日志的大小。然后选择“计划”选项卡，在“启动日志控件”组中，将启动时间更改为当天晚上 11:50 开始。然后，在“停止日志控件”组下，选择“固定时间”单选按钮，并将停止时间更改为第二天凌晨 12:10。

这些事件（进程创建/删除、线程创建/删除）会很快累积大量数据。根据正在运行的内容，您可以期望这些数据以千兆字节（或更大）为单位，并且如果您填满了运行 Windows 或其他应用程序的磁盘驱动器，则会发生糟糕的事情。理想情况下，您会将此记录到专用位置，即单独的分区或外部驱动器。您可以在“常规”选项卡中的“当前日志文件名”文本框（顶部）中更改日志文件的位置。或者，您可以更改计划，使其在日志达到特定大小时停止，而不是在特定时间停止，但无法提前知道给定磁盘大小会花费多少时间 — 这取决于实际触发了多少事件。

Microsoft 的 Log Parser 工具

跟踪生成的事件跟踪日志文件 (ETL) 不易直接阅读。您可以使用 OS 工具 `TraceRpt.exe` 来生成几个标准报告（`Summary.txt` 和 `Workload.txt`）以及一个逗号分隔值 (CSV) 文件，该文件可以使用 Excel 或文本编辑器进行检查，但这些文件中的信息并不容易获得。相反，您可以下载 Microsoft LogParser 工具的最新版本。您可以访问 www.Microsoft.com，从“下载与试用”菜单中单击“下载中心”链接，然后搜索 LogParser 以查找最新版本。我使用的是LogParser 2.2 版。

安装 LogParser 实用程序后，您将在“开始”菜单下看到“Log Parser Program Group”及其下的“Log Parser”应用程序。运行该应用程序会打开一个命令终端（DOS），其中包含 LogParser 的命令帮助。要将数据导出到 XML，您应该运行命令

LogParser -i:ETW "SELECT * INTO C:\PerfLogs\Pikachu_000004.XML 
FROM C:\PerfLogs\Pikachu_000004.etl" -o:XML

如所示，此命令将读取并解析第四个跟踪日志文件 `Pikachu_000004.etl`，并将结果导出到文件 `Pikachu_000004.xml`。应在上面的命令中修改特定的输入文件和输出文件以匹配您的情况。从这里，您应该看到每个事件作为一个单独的 `ROW` 节点。这些事件最初是按时间顺序记录的，因此在输出文件中也是按时间顺序排列的。您可以通过在查询末尾附加“ORDERBY Timestamp ASC”来添加排序顺序，以确保这一点。按时间排序的数据对于定位特定时间事件很重要 — 从这里我们可以向前查找数据，直到找到性能下降前几分钟的事件。

发现

不幸的是，在性能异常之前没有线程或进程启动，所以我的结果不能用于本文。问题最终是日志记录任务中的一个 bug，它没有考虑到零点小时。这是在调查了应用程序日志为何未记录初始计数器日志记录中观察到的任务重启之后才发现的。然而，在您自己的疑难解答工作中，如果您发现了值得追溯的内容，您可以在 XML 输出中找到每个线程的 `ProcessId`。这可用于将线程追溯到特定进程。大多数进程在 `UserData` 下都有一个 `ImageFileName`，可用于识别特定应用程序。

这是一个线程在 13:35:53 启动的示例。

<eventnumber>  2464 </eventnumber>
  <eventname>
  Thread  </eventname>
  <eventtypename>
  Start  </eventtypename>
  <timestamp>
  2010-12-13 13:35:53  </timestamp>
  <userdata>
  ProcessId=856|TThreadId=3020|StackBase=0xA9B0B000|StackLimit=0xA9B08000|
  UserStackBase=0x00940000|UserStackLimit=0x0093A000|StartAddr=0x7C8106F9|
  Win32StartAddr=0x75738D6B|WaitMode=ÿ
</userdata> </row>

这里的 `ProcessId` 是 `856`。搜索此进程 ID 的 XML 文件会显示几个额外的线程，但在 13:12:00，会记录该进程的 `DCStart` 事件。在这一行中，您可以看到启动所有这些线程的应用程序的名称。

<row><eventnumber>  233
</eventnumber>  <eventname>
  Process
</eventname>  <eventtypename>
  DCStart
</eventtypename>  <timestamp>
  2010-12-13 13:12:00
</timestamp>  <userdata>
  PageDirectoryBase=0x0000C1EA|ProcessId=856|ParentId=796|SessionId=0|
  ExitStatus=0|UserSID=S-1-5-18|ImageFileName=lsass.exe</userdata>

计数器和跟踪为快速识别复杂 bug 提供了全新的机会。随着软件复杂性的不断增长，诸如这些工具之类的工具对于日常编程变得越来越重要。我鼓励您花点时间研究这些工具的其他用途。如果您这样做，您会发现，正如我所发现的那样，它们更适合管理长期运行的服务器，而不是短期调试工作。然而，随着其有用性的不断证明，将会有更多工具被开发出来，以便更好地关联因果事件。数据就在那里，但梳理原始 XML 文件几乎不是将线程与性能事件的变化相关联的首选方法，更不用说将线程追溯到特定应用程序了。尽管如此，我希望您在自己的调试工作中尝试这些工具。它们的潜力是巨大的。

历史

• 初版。2010 年 12 月 12 日
• 添加了图像。2010 年 12 月 27 日
• 语法和拼写更正。2010 年 12 月 28 日