Linux性能优化--性能追踪2：延迟敏感的应用程序

11.0 概述

本章包含了一个例子：如何用Linux性能工具在延迟敏感的应用程序中寻找并修复性能问题。
阅读本章后，你将能够：

1. 在延迟敏感的应用程序中用ltrace和oprofile弄清楚哪里产生了延迟。
2. 对“热点”函数的每个调用，用gdb生成栈跟踪。
3. 用性能工具确定使用了多个不同共享库的应用程序是如何消耗时间的。
4. 以本章为模板，找出延迟敏感应用程序中高延迟的原因。

11.1延迟敏感的应用程序

本章我们将调查一个应用程序，该程序对长延迟敏感。延迟可以被认为是一个应用程序响应不同的外部或内部事件所花费的时间。具有延迟性能问题的应用程序一般不是长时间占用CPU,相反，它只用少量的CPU时间来响应不同的事件。但是，这种响应对特定事件来说是不够的。在修复延迟性能问题时，我们需要降低对各种时间的响应延迟，并找出是应用程序的哪些部分延缓了响应。正如你将看到的，与追踪受CPU限制的问题相比，追踪延迟问题需要的策略略有不同。

11.2 确定问题

对前一章的性能问题，我们必须定义调查内容，并尝试去克服它。本章中，我们把这个过程优化一下，使用GNOME桌面的nautilus文件管理器打开一个弹出菜单。在nautilus 文件管理器窗口的任何位置点击右键即可打开弹出菜单。在这种特定情况下，我们将调查鼠标右键点击一个打开窗口的背景时弹出菜单显示的性能，而不是鼠标右键点击一个特定文件或文件夹时弹出菜单的显示性能。
为什么要对这进行优化?即使打开一个弹出菜单的时间比一秒钟还要少，但它仍然慢到足以让用户感觉到自己点击鼠标右键与菜单显示之间的时间差。这种缓慢的弹出带给GNOME用户的印象是计算机运行的速度慢。人们注意到轻微的延迟，它会让与nautilus的交互变得烦人，或是给人留下桌面迟缓的印象。
这个特殊的性能问题与前一章中的GIMP问题不同。第一，桌面(本例中为GNOME)的核心组件通常比一个典型的桌面应用程序更为复杂与交错。这些组件为了完成工作一般要依赖于各种各样的子系统和共享库。而GIMP是一个相对独立的应用程序，这使得它更容易分析，并在必要的时候重新编译。GNOME桌面则不同，它是由多个不同的交错组件构成的。这些组件可能需要多个进程和共享库，其中每个库都代表桌面执行不同的任务。尤其是nautilus,它链接了72个不同的共享库。追踪到底是哪一段代码消耗了时间，消耗了多少，为什么消耗，可以说是一个艰巨的任务。
本章性能调查与GIMP调查第二个明显不同的地方是：我们想要减少的时间是以毫秒计，而不是以秒或分钟计。当时间小到这个程度，就很难确保捕获到的性能分析数据确实就是你设法测量的事件结果，而不只是尝试停止和启动分析工具时周围的噪声。不过，这个短暂的时间周期还是能在你感兴趣的时间内实际跟踪应用程序工作的方方面面。

11.3找到基线/设置目标

在前一个性能追踪案例中，第一步是确定问题的当前状态。为了让我们的工作更容易一点，并且回避一些上一节提到的分析问题，我们要耍点小花招，让弹出菜单问题看起来更像之前我们测量过的长时间运行的CPU密集型任务。单个弹出菜单显示的时间是毫秒级的，这使得用我们的性能工具很难进行精确的测量。如前所述，很难在合适的时间启动和停止工具，并确保我们只测量到了感兴趣的(即，打开确切菜单所花的CPU时间)。我们将在这里玩点小技巧。我们将快速连续地打开菜单100次，而不仅仅只打开一次。这样，菜单打开的总时间将会达到100倍。这使得我们能用剖析工具捕获菜单正如何执行的信息。
由于右键点击100次很乏味，且人类(除非非常训练有素)不可能可靠地重复打开一个弹出菜单100次，所以我们必须将这个过程自动化。要可靠地打开弹出菜单100次，我们依赖于xautomation包，该包可以从http://hoopajoo.net/projects/xautomation.html获得。它可以模拟一个用户，向X服务器发送任意的X Window事件。下载xautomation压缩包，解压并编译后，就可以使用它来自动执行点击鼠标右键。
与对待GIMP不同，我们不能简单地通过测量nautilus使用的CPU时间来计算创建100个弹出菜单所需的时间。这主要是因为nautilus不能在菜单被打开前立即启动，也不能打开后立即结束。我们将使用墙钟时间来查看完成这个任务需要耗时多久。这要求在进行测试时，系统没有运行任何其他的事情。
清单11.1给出了xautomation命令的shell脚本，用于在nautilus文件浏览器中打开100 个弹出菜单。运行测试时，我们必须确保面对的是nautilus窗口，这样就不会有点击实际上是打开了文件夹的弹出菜单，而是所有的弹出窗口都出现在背景上。这是非常重要的，因为不同弹出菜单的代码路径可能是完全不同的。

清单11.1中的命令把光标放置在X屏幕的(100,100)处，点击鼠标右键(按钮3)。这个操作打开一个菜单。然后它们再次右击鼠标，这次是关闭该菜单。之后移动到X位置(200,100),重复该过程。
接下来，我们用time查看完成这个100次迭代脚本花费了多少时间。这就是我们的基线时间。在我们进行优化时，我们将把优化结果与这个时间作比较看看是否有所改进。我的笔记本为普通版Fedora2的nautilus,该条件下的基准时间为26.5秒。
最后，我们要为优化选择一个目标。实现这个目的的一个简单方法是找到一个已经具备快速弹出菜单的应用程序，查看它打开100次弹出菜单消耗的时间。xterm是这方面一个很好的例子，它有非常敏捷的菜单。虽然这些菜单不像nautilus的一样复杂，但是它们至少应该被看作是菜单速度的上限。
xterm的弹出菜单操作略有不同，因此我们需要稍微修改一下创建100个弹出菜单的脚本。当xterm创建一个弹出菜单时，需要按下左控制键，因此我们必须对自动化脚本进行轻微的改动。该脚本如清单11.2所示。

运行xterm并对创建弹出菜单进行计时，xterm完成该脚本的时间约为9.2秒。nautilus 有相当大的提升空间(几乎为17秒)。期望创建nautilus复杂弹出菜单的速度与xterm的一样可能是不合理的，因此我们保守地将目标设定为10%,即3秒钟。我们希望能够做得比这更好，或者至少弄清楚速度为什么不能更快了。

11.4为性能追踪配置应用程序

调查的下一步是为性能追踪设置应用程序。对GIMP我们立即重编译了应用程序，而对nautilus我们将采取不同的方法。由于要依赖于很多不同的共享库，因此很难指出究竟是哪些地方需要重编译。我们不进行重编译，取而代之的是下载并安装每个应用程序和库的调试信息。对Fedora和企业版Linux,Red Hat提供了一组dubuginfo rpm,其中包含了应用程序编译时，编译器生成的全部符号信息和源代码。每个二进制包或库都有相应的dubuginfo rpm提供其调试信息。这使得Red Hat可以传输二进制文件，而不用带上占用磁盘空间的调试信息。但是，它又允许开发人员或那些调查性能问题的人下载并使用合适的debuginfo包。在这种情况下，Red Hat版本的oprofile也可以识别debuginfo包，并在分析应用程序(如一个nautilus)和库(如gtk)时获取符号。本例中，我们将下载gtk、nautilus、glib和内核的debuginfo。如果oprofile发现一个库占用了大量的周期，但又不允许你分析这些库(oprofile输出“nosymbols”),这就表示没有安装该库的调试信息。我们可以下载并安装适合该库的debuginfo包，之后oprofile将访问调试信息，并可以把事件映射回原始函数和源代码行。

11.5安装和配置性能工具

追踪的下一步是按照调查问题所需的性能工具。如同对GIMP性能追踪所做的一样，我们将安装oprofile和ltrace。本例中，我们还将下载并安装gdb(如果它还未安装)。gdb 可以让我们观察运行中应用程序的一些动态方面。

11.6运行应用程序和性能工具

下面，我们运行应用程序，并使用性能工具进行测量。由于我们已经假设多个不同的进程和库之间的复杂交互可能是问题产生的原因，我们将从oprofile开始，看看它给了些什么信息。
我们希望oprofile只测量弹出菜单打开时发生的事件，所以我们将使用如清单11.3所示的命令行在脚本(名为script.sh)开始运行的前一刻立即启动分析，在结束运行的后一刻立即停止分析，该脚本打开和关闭弹出菜单100次。

收集分析信息之后运行opreport,得到如清单11.4所示的信息。

正如你所看到的，耗时分散在多个不同的库中。可惜的是，并不完全清楚这些调用是属于哪个应用程序的。尤其是，我们不知道哪个进程调用了libgobject库。幸运的是，oprofile提供了一种方法来记录应用程序运行时使用的共享库函数。清单11.5显示了如何配置oprofile的样本采集来按库分离样本，这就意味着oprofile会把共享库中采集的样本按照调用库的程序来划分。

(用清单11.3的命令行)重新运行测试后，opreport分离了每个应用程序的库样本，如清单11.6所示。

如果我们更深入的探究libgobject和libglib库，就能清楚地看到哪些函数被调用了，如清单11.7所示。


从oprofile的输出可以看出nautilus在libgobject库上花费了相当多的时间，尤其是g_type_check_instance_is_a函数。但是，目前还不清楚nautilus文件管理器中哪些函数进行了这些调用。实际上，这些函数可能不是直接由nautilus调用的，而是由调用这nautilus的其他共享库调用的。接下来我们使用共享库追踪器Itrace尝试找出哪些库调用开销最大，以及最终是谁调用了g_type_check_instance_is_a函数。我们主要关注的是nautilus调用了哪些函数，而不是精确的计时信息，它只有在打开弹出菜单一次而非100次时才是重要的。因为ltrace会捕捉单次运行的每一个共享库调用，所以，如果我们创建100个弹出菜单，ltrace就会显示相同的分析信息100次。
捕捉共享库使用情况信息的过程类似于我们在GIMP中做的。我们首先正常启动nautilus。之后，在打开一个弹出菜单之前，使用如下ltrace命令附加到nautilus进程：
ltrace -c -p <pid_of_nautilus>
在nautilus背景上点击右键，打开菜单，接着立即用组合键中止Itrace进程。跟踪弹出菜单后，我们得到如清单11.8所示的汇总表。

在这个表中，我们可以看到一些有趣的地方。ltrace在顶部显示了一个与oprofile完全不同的函数。这主要是因为oprofile和ltrace测量的内容略有不同。oprofile显示的是实际函数耗费的时间，但不包括子函数。ltrace则仅显示外部库调用完成耗费的时间。如果库函数反过来还要调用其他函数，那么ltrace不会记录每一个的时间。事实上，目前它甚至都不会检测或显示发生的这些其他库调用。
在这种特定情况下，oprofile所说的libgobject的最热函数(即g_type_check_instance_is_a)几乎根本不会出现在ltrace分析信息中。即使这个函数是共享库的一部分，对它的调用也没有显示在ltrace的输出中。ltrace不能显示跨库调用，也不能显示库内调用。1trace 只能跟踪外部库调用或者一个共享库内的应用程序调用。当一个库调用一个内部函数时，ltrace不能跟踪此调用。在这种情况下，所有前缀为g_的函数实际上都是libgobject库的一部分。它们其中的任何一个调用g_type_check_instance_is_a,ltrace都无法检测到。
ltrace提供的最重要的信息是我们的应用程序调用的几个库，我们将对它们进行调查。我们可以弄清楚库是在哪里被调用的，以及为什么这个库调用消耗了所有的时间。

11.7编译和检查源代码

现在，我们有了关于占用全部时间的应用程序调用的一些信息，我们将下载源代码并对其编译。到目前为止，我们所有的分析都可以通过使用Red Hat提供的二进制包进行。但是，现在我们需要深入源代码，检查热点函数被调用的原因，找出原因后，修改源代码来缓解性能问题。如同对GIMP所做的，重编译时，在调用配置脚本之前，我们设置CFLAGS为-g以生成调试符号。
本例中，我们为nautilus下载并安装Red Hat的源rpm,它把nautilus源代码放在/usr/src/redhat/SOURCES中。通过使用Red Hat的源代码包，我们有了Red Hat在包内用于创建二进制文件的准确源代码和补丁。重要的是研究用于创建我们一直调查的二进制文件的源代码，因为不同的版本就可能有不同的性能特点。提取源代码后，我们就可以开始找出bonobo_window_add_popup是在哪里调用的。可以用清单11.9中的命令搜索nautilus目录下的所有源文件。

幸运的是，看上去bonobo_window_add_popup似乎只被一个函数create_popup_menu 调用，如清单11.10所示。

反过来，该函数被其他两个函数调用，fm_directory_view_pop_up_background_context_menu和fm_directory_view_pop_up_selection_context_menu。在这两个函数上都添加printf,我们就可以确定当右键点击窗口时调用的是哪一个了。之后对nautilus进行重编译，并运行它，在窗口背景上点击右键。nautilus输出fm_directory_view_pop_up_background_context
menu,由此我们知道在窗口背景上打开弹出菜单时调用的就是这个函数。该函数的源代码如清单11.11所示。


现在我们已经准确缩小了弹出菜单创建与显示的范围，我们就可以开始弄清楚究竟是哪些部分消耗了这些时间，又是哪些部分最终调用了g_type_check_instance_is_a函数，即oprofile所说的热点函数。

11.8使用gdb生成调用跟踪

检索应用程序调用了哪些函数的两种不同的工具提供给我们哪个函数是热点函数的信息也是不一样的。我们推测ltrace报告的高级函数调用了oprofile报告的低级函数。要是有性能工具能告诉我们到底是哪些函数调用了g_type_check_instance_is_a以验证这个理论就好了。
虽然没有Linux性能工具向我们显示究竟是哪些函数调用了某个特定函数，但gprof应该能显示这个回调信息，不过这需要用-pg选项重新编译应用程序及其依赖的所有库。对nautilus而言，它依赖于72个共享库，这让任务变得无比艰巨，因此，我们必须寻找其他的解决方法。较新版本的oprofile也可以提供这类信息，但是由于oprofile只进行定期采样，所以它还是不能解释对任意给定函数的每一次调用。
幸运的是，我们可以创造性地利用gdb来提取信息。用gdb来跟踪应用程序会极大地降低运行速度，不过，我们并不真正在意跟踪是否需要很长的时间。我们感兴趣的是发现一个特定函数被调用的次数而不是它被调用的时长，因此，运行需要很长的时间也是可以接受的。幸好弹出菜单的创建是毫秒级的，即便使用gdb使其速度慢了1000倍，提取全部跟踪信息也仍然只需要15分钟。信息的价值远远超过了我们等待检索的价值。
尤其是要找出是哪些函数调用了g_type_check_instance_is_a时，我们需要用到gdb几个不同的功能。首先，要使用gdb设置断点的功能。然后，要用到gdb在该断点上用bt生成回溯的功能。要弄清楚哪些函数调用了g_type_check_instance_is_a,我们确实需要这两个功能，不过手工记录信息并继续是单调乏味的。我们要在函数的每次gdb中断之后键入bt;cont。
要解决这个问题可以使用gdb的另一个功能。在遇到一个断点时，gdb可以执行一组给定的命令。通过使用command命令，我们可以告诉gdb,每次在函数中遇到断点时，它都要执行bt;cont。现在，回溯自动显示，且应用程序每次遇到g_type_check_instance_is_a时都会继续运行。
当实际运行跟踪时需要进行分离。我们可以只在nautilus开始执行时在g_type_check_instance_is_a中设置断点，当其被其他函数调用时，gbd就会显示跟踪信息。由于我们只关注创建弹出菜单时被调用的那些函数，我们想要将跟踪只限制在弹出菜单被创建的时候。要做到这一点，需在fm_directory_view_pop_up_background_context_menu函数的开始和结束的地方设置另一个断点。当到达第一个断点时，我们打开g_type_check_instance_is_a中的回溯。当到达第二个断点时，退出调试器。这就把生成的回溯信息限制在了创建弹出菜单的时候。最后，我们希望能够保存这些回溯信息以便后期处理。我们可以使用gdb将其输出记录到文件的功能，为后续保存信息。为了提取这些信息而传递给gdb的命令如清单11.12所示。

运行这些gdb命令，打开弹出菜单，gdb运行几分钟后，创建了一个33MB的文件，包含了调用g_type_check_instance_is_a的函数的全部回溯信息。清单11.13给出了其中的一个样本。

尽管这个信息非常详细，但它的格式实在是不易于阅读。如果每个回溯都在单独一行上，且用箭头分隔每个函数就会好一点。去掉对fm_directory_view_pop_up_background_context_menu调用上面的回溯信息也是很好的，因为我们知道每一个这样的调用都有同样的回溯信息。利用清单11.14所示的Python程序slice.py可以做到这一点。该程序用gdb 生成的详细输出文件，对每个调用fm_directory_view_pop_up_background_context_menu的函数创建一个格式良好的调用跟踪。


用清单11.15中的命令行在这个Python程序中运行gdb.txt文件，会得到一个合并度更高的输出，清单11.16给出了一个例子。


由于输出行很长，本书显示时它们已经换行，但是在文本文件中一个回溯一行。每行都用g_type_check_instance_is_a函数结束。因为一个回溯只占用一行，我们就可以用一些常见的Linux工具来抽取回溯信息，比如wc,该工具可以用于计算特定文件的行数。
首先，我们看看有多少对g_type_check_instance_is_a函数的调用。该值与回溯的数量相同，因此也与backtrace.txt文件的行数相同。清单11.17显示了被精简回溯文件调用的wc命令。第一个数字表示的是文件的行数。

可以看到，只是创建弹出菜单，函数就被调用了6848次。接下来看看这些函数调用中有多少是代表bonobo_window_add_popup发起的，查看清单11.18。

bonobo_window_add_popup负责了6670次热点函数的调用。查看backtrace.txt文件发现，其中的一些是直接调用，而大多数则来自于它调用的其他函数。从这点来看，好像bonobo_window_add_popup确实应为大部分消耗掉的CPU时间负责。不过，我们还是要对这种情况进行确认。

11.9找到时间差异

现在我们已经缩小到了是由哪些函数创建了菜单，我们想要弄清楚哪些部分占用了所有的时间，哪些部分相对是轻量级的。有一个很好的方法能做到这一点，并且不需要使用任何性能工具，即只需禁用代码段，查看它是如何改变性能的。尽管这会导致nautilus功能失常，但它至少能表明哪些函数占用了所有的时间。
首先我们要从获取基线开始，因为与Red Hat提供的相比，正在测试的二进制文件已经用不同的标志编译过了。和之前一样对脚本计时。此时，在我们自己编译的版本中，运行100次迭代花费了30.5秒。接着，我们注释掉eel_pop_up_context_menu调用。这会告诉我们nautilus花了多少时间来检测鼠标点击并决定应创建一个右键菜单。即使完全优化掉这些函数中的所有命令，也无法运行地更快。这种情况下，运行全部100次迭代耗时7.6秒。接下来，我们注释掉bonobo_window_add_popup,看看调用ltrace所说的占用最多时间的函数实际上消耗了多少时间。如果注释掉bonobo_window_add_popup,完成100次迭代耗时21.9秒。这就是说，如果我们优化掉bonobo_window_add_popup,总的运行时间可以减少大约8秒，性能提升了几乎25%。

11.10尝试一种可能的解决方案

所以，如我们所见的一样，bonobo_window_add_popup是开销很大的函数，但又是每次想要创建弹出菜单时必须调用的函数。如果用同样的参数重复调用该函数，说不定可以缓存其从初始调用返回的值，并且在之后的每一次调用时都使用该值，以代替对该昂贵函数的重复调用。清单11.19显示了一个重写函数的例子，来完成这个功能。


本例中，我们记住了上一次生成的菜单。如果呈现在同一视图中，且我们认为该视图的菜单没有改变，那么只需要使用与上一次相同的菜单，而不用创建新的。这个技术并不复杂，如果用户没有在同一个目录中重复打开弹出菜单就会出问题。举个例子，假如用户在目录1中打开了一个弹出菜单，然后又在目录2中打开一个，之后又在目录1里打开一个弹出菜单，那么nautilus还是会创建一个新菜单。可以建立一个简单的缓存，在菜单被创建时保存它们。打开菜单时，首先检查这些视图是否已经有在缓存中的菜单。如果是，就显示被缓存的菜单，否则将创建新菜单。这个缓存对一些特殊的目录非常有用，如桌面、计算机或主目录，在这些目录中用户很可能多次打开弹出菜单。应用上述解决方案后，对100次迭代计时，其所用时间减少到24.0秒。性能提升约20%,接近于不创建任何菜单时可以获得的理论改进值(21.9秒)。在不同目录中创建弹出菜单与预期一致。这个补丁似乎没有任何破坏性。
但是要注意，现在这只是一个测试解决方案。它需要被提交给nautilus开发人员，以确认该方案没有破坏任何功能，且适合添加。不过在整个追踪的过程中，我们已经确定了哪些函数慢，跟踪了它们在哪里被调用，创造了一个可能的解决方案，它在客观上改进了性能。请注意，改进是客观的，这一点很重要。也就是说，我们有确凿的数据证明新方法更快，而不是简单的主观印象(只是说感觉更迅捷了)。大多数开发人员都想要这样的性能bug报告。

11.11本章小结

本章我们确定了为什么应用程序的特定部分会有高延迟(nautilus中的弹出菜单)。我们弄清楚了怎样将弹出菜单的创建进行自动化(xautomation),以及怎样扩展nautilus在创建弹出菜单时花费的时间(100次迭代)。我们用oprofile来了解nautilus在哪些函数上消耗了全部时间，然后用ltrace和gdb确定哪些共享库调用应该对所有的调用负责。在明确了哪些库调用具有高成本后，我们试图减少或限制它们被调用的次数。针对这种情况，当一个新菜单被创建时，我们保存一个指针指向它，之后使用就可以避免不必要的重新分配。我们创建了一个建议补丁，然后在其上运行性能测试看看是否可以提升性能。性能提高了，并且功能看上去没有受到影响。下一步就是把这个补丁提交给nautilus开发人员讨论。本章侧重于优化单个应用程序的延迟，下一章给出的性能追踪则集中于解决系统级的性能问题。这种类型的追踪常常涉及对系统多个不同方面的调查，包括硬件(磁盘、网络和内存)与软件(应用程序、共享库和Linux内核)。