我应该如何解释 OProfile 输出？答案

【问题标题】：How am I supposed to interpret OProfile output?我应该如何解释 OProfile 输出？
【发布时间】：2011-05-01 09:00:45
【问题描述】：

我最近尝试使用 OProfile 分析我的应用程序。收集到的数据对我来说已经很有价值，但我很难准确解释。运行我的应用程序并设置并运行 oprofile 后，我生成了报告并得到：

root@se7xeon:src# opreport image:test -l -t 1
溢出统计信息不可用
CPU：P4 / Xeon，带 2 个超线程，速度 3191.66 MHz（估计）
计数 GLOBAL_POWER_EVENTS 事件（处理器未停止的时间），单位掩码为 0x01（强制）计数 750000
示例 % 符号名称
215522 84.9954 cci::Image::interpolate(unsigned char*, cci::Matrix const&) const
17998 7.0979 cci::Calc::diff（无符号字符常量*，无符号字符常量*）
13171 5.1942 cci::Image::getIRect(unsigned char*, int, int) 常量
5519 2.1765 cci::Image::getFRect(unsigned char*, double, double) const

好的，所以我的插值函数占应用程序（太长）执行时间的 84%。似乎是个好主意：

root@se7xeon:src# opannotate image:test --source
[...]

/* cci::Image::interpolate(unsigned char*, cci::Matrix<cci::Point2DF> const&) const total: 215522   84.9954 */  
1392  0.5529 :void Image::interpolate(CCIPixel *output, const Matrix<Point2DF> &inputPoints) const throw()  
4  0.0016 :{  
[...]  
:                col0 = static_cast<int>(point[idx].x);  
3  0.0012 :      col1 = col0+1;  
629  0.2498 :    row0 = static_cast<int>(point[idx].y);  
385  0.1529 :    row1 = row0+1;  
56214 22.3266 :  if (col0 < 0 || col1 >= m_width || row0 < 0 || row1 >= m_height)  
:                {  
:                        col0 = row0 = col1 = row1 = 0;  
:                }

如果我理解正确的话，if 条件占程序执行时间的 22% 以上。左大括号和函数声明似乎需要时间，这应该对应于函数调用开销（“入栈参数，跳转，弹出参数”序列）？

我更改了源代码中的一些内容（与后来的瓶颈有关，因为我不知道如何优化 if），重新编译，再次运行 oprofile（不要忘记 opcontrol --reset）。现在注释代码在同一个地方看起来像这样：

6  0.0024 :     curPx = point[idx].x;  
628  0.2477 :   curPy = point[idx].y;  
410  0.1617 :   col0 = static_cast<int>(curPx);  
57910 22.8380 : col1 = col0+1;  
:               row0 = static_cast<int>(curPy);  
:               row1 = row0+1;  
:               if (col0 < 0 || col1 >= m_width || row0 < 0 || row1 >= m_height)  
:               {  
:                   col0 = row0 = col1 = row1 = 0;  
:               }

这一次 if 基本上不占用时间（？），最昂贵的指令是“col1 = col0 + 1”，整个耗时块似乎已经向上移动。怎么会这样？可以完全相信这可以查明源中的瓶颈吗？

我的另一个疑问是，当我设置 opcontrol 时，我将跟踪事件输入为 GLOBAL_POWER_EVENTS，样本数为 750k。在输出中，插值函数似乎占用了 84%，但其中记录的样本数仅略高于 200k。这甚至不是请求数量的 50%。我是否理解剩余的约 500k 样本是由未在输出中列出的应用程序（内核、Xorg 等）获取的？

【问题讨论】：

标签： c++ linux profiling oprofile

【解决方案1】：

在分析优化代码时，您确实不能依赖准确的源代码行。编译器移动的东西太多了。

要获得准确的图片，您需要查看代码反汇编器输出。

【讨论】：

如果我对未优化的版本进行分析是否有意义？还是其中发现的瓶颈与优化版本完全无关？另外，有什么方法可以获得百分比注释的反汇编程序输出？ ;)
哇，显然有一个名为 --assembly 的 opannotate 选项，谢谢！

【解决方案2】：

OProfile 可以（他们告诉我）在挂钟时间（而不是 CPU）上获取堆栈样本，它可以为您提供行级百分比。您正在寻找的是包含在大部分堆栈样本中的行。

在我完成手动调整代码之前，我不会打开编译器优化，因为它只是隐藏了一些东西。

当您说插值例程使用 84% 的时间时，就会触发一个问题。整个程序需要一些总时间，对吧？这需要 100% 的时间。如果你把程序的时间减半，或者加倍，它仍然需要 100% 的时间。 84% 的插值是否过多取决于是否超出必要。

所以我建议你不要问例行程序的百分比是否太多。相反，您寻找花费大量时间的代码行并询问它们是否可以优化。看到不同？优化代码后，它可以大大减少整体运行时间，但它可能仍然是一个较小的总数的很大百分比。当没有什么占很大比例时，代码不是最佳的。当占很大比例的所有事情中没有一个可以改进时，代码是最佳的。

我不喜欢只给出数字的东西。我想要的是洞察力。例如，如果该例程占 84% 的时间，那么如果您使用 10 samples of the stack，它将在其中的 8.4 上。确切的数字无关紧要。重要的是要了解为什么它在那里。真的有必要在里面这么多吗？这就是查看堆栈样本可以告诉你的。也许您实际上是根据需要多次进行插值？通过分析为什么，人们经常会发现，他们试图加速的例程几乎不需要调用，也许根本不需要调用。我猜不出你的情况。只有通过检查程序状态的洞察力才能告诉您这一点。

【讨论】：