Oprofile 和 gprof 输出因相同代码而异答案

【问题标题】：Oprofile and gprof output varies for same codeOprofile 和 gprof 输出因相同代码而异
【发布时间】：2013-02-22 11:44:27
【问题描述】：

我正在运行我的代码 AMD optron 6270 机器。操作系统是 Centos 6.2 版本。我做了一个简单的程序

#include<stdio.h>
#include<stdlib.h>
int calling (long a);
int calling1 (long a);
int calling2 (long a);
int calling3 (long a);
int calling4 (long a);
int calling5 (long a);

void main()
{
    long a,b=0;
    printf("hi");
    for (a=0; a<10000000; a++) b++;
    b =Calling(a);
    b =Calling5(a);
    b =Calling4(a);

}

int Calling(long a)
{
    long b=0;
    for (a=0; a<100; a++) b = Calling1(a);
    return 0;
}

int Calling1(long a)
{
    long b=0;

    for (a=0; a<10000000; a++) b++;
    b =Calling2(a);
    return 0;
}

int Calling2(long a)
{
    long b=0;
    for (a=0;a<10000000;a++) b++;

    b =Calling3(a);
    return 0;
}
int Calling3(long a)
{
    long b=0;
    for (a=0;a<10000000;a++) b++;
    b =Calling4(a);
    return 0;
}
int Calling4(long a)
{
    long b=0;
    for (a=0; a<10000000; a++) b++;
    return 0;
}

int Calling5(long a)
{
    long b=0;
    for (a=0; a<10000000; a++) b++;
    b=0;
    for (a=0; a<10000000; a++) b++;
    b=0;
    for (a=0 ;a<10000000; a++) b++;
    b=0;
    for (a=0; a<10000000; a++) b++;
    b=0;
    return 0;
}

在使用 gprof 和 Oprofile 分析此代码时。我得到了不同的报告。假设我用 gprof 运行 main.exe 两次： gprof 的第一份报告平面轮廓：

每个样本计为 0.01 秒。

  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name

 24.80      2.96     2.96      101     0.03     0.03  Calling4
 24.71      5.91     2.95      100     0.03     0.12  Calling1
 24.63      8.84     2.94      100     0.03     0.06  Calling3
 23.78     11.68     2.84      100     0.03     0.09  Calling2
  1.01     11.80     0.12        1     0.12     0.12  Calling5
  0.34     11.84     0.04                             main
  0.00     11.84     0.00        1     0.00    11.65  Calling

gprof 的第二次报告

平面轮廓：

每个样本计为 0.01 秒。

% 累计自我自我总计
time seconds seconds 呼叫 s/呼叫 s/呼叫名称

 25.13      2.99     2.99      100     0.03     0.12  Calling1
 24.88      5.95     2.96      101     0.03     0.03  Calling4
 24.80      8.89     2.95      100     0.03     0.06  Calling3
 23.48     11.69     2.79      100     0.03     0.09  Calling2
  1.02     11.81     0.12        1     0.12     0.12  Calling5
  0.17     11.83     0.02                             main
  0.00     11.83     0.00        1     0.00    11.66  Calling

两个报告不同。每次我运行我的 main.exe 时，我都会得到不同的分析报告。当我尝试 Oprofile 时，我也得到了不同的结果：

Oprofile 报告1 使用 /var/lib/oprofile/samples/ 作为示例目录。警告：找不到 /no-vmlinux。 CPU：AMD64 family15h，速度2.2e+06 MHz（估计）计数 CPU_CLK_UNHALTED 事件（CPU 时钟未停止），单位掩码为 0x00（无单位掩码）计数 100000

samples  %        image name               symbol name
92552    24.7672  main                     Calling4
91610    24.5151  main                     Calling3
91566    24.5033  main                     Calling1
91469    24.4774  main                     Calling2
3665      0.9808  main                     Calling5
1892      0.5063  no-vmlinux               /no-vmlinux
916       0.2451  main                     main
10        0.0027  libc-2.12.so             profil_counter
1        2.7e-04  ld-2.12.so               _dl_cache_libcmp
1        2.7e-04  ld-2.12.so               _dl_relocate_object
1        2.7e-04  ld-2.12.so               _dl_sysdep_start
1        2.7e-04  ld-2.12.so               strcmp
1        2.7e-04  libc-2.12.so             __libc_fini
1        2.7e-04  libc-2.12.so             _dl_addr
1        2.7e-04  libc-2.12.so             _int_malloc
1        2.7e-04  libc-2.12.so             exit

Oprofile 报告2

使用 /var/lib/oprofile/samples/ 作为示例目录。警告：找不到 /no-vmlinux。 CPU：AMD64 family15h，速度2.2e+06 MHz（估计）计数 CPU_CLK_UNHALTED 事件（CPU 时钟未停止），单位掩码为 0x00（无单位掩码）计数 100000

samples % 图像名称符号名称

92254    24.7719  main                     Calling4
91482    24.5646  main                     Calling1
91480    24.5641  main                     Calling3
91340    24.5265  main                     Calling2
3658      0.9822  main                     Calling5
1270      0.3410  no-vmlinux               /no-vmlinux
916       0.2460  main                     main
6         0.0016  libc-2.12.so             profil_counter
1        2.7e-04  ld-2.12.so               _dl_lookup_symbol_x
1        2.7e-04  ld-2.12.so               _dl_setup_hash
1        2.7e-04  ld-2.12.so               _dl_sysdep_start
1        2.7e-04  ld-2.12.so               bcmp
1        2.7e-04  libc-2.12.so             __mcount_internal
1        2.7e-04  libc-2.12.so             _dl_addr
1        2.7e-04  libc-2.12.so             _int_free
1        2.7e-04  libc-2.12.so             mcount

谁能告诉他们为什么会这样？造成这种情况的可能原因是什么？如何避免这种情况，以便获得持续的分析结果？

【问题讨论】：

这是一个随机过程。如果测量是精确可重复的，那将是一个错误。看大局。
在您的测试期间，操作系统将被其他进程、I/O 等占用。无法保证机器在测试期间的状态与后续测试期间的状态相匹配。您可以将机器置于单用户模式，这可能会减少时间的变化。
有什么办法可以得到精确的结果。因此，如果我正在做小的优化（比如 5 毫秒），我应该能够在报告中看到。
这就是你的做法。对于每个优化，运行 N 次测试，例如 10 或 100。然后获取您感兴趣的时间的平均值和标准偏差。在您的报告中使用它。
感谢您的快速cmets。

标签： linux profiling centos gprof oprofile

【解决方案1】：

我不会担心后续报告的不同。根据程序的执行方式，报告可能会有很大差异。此外，很难说这两个配置文件之间发生了什么。根据正在运行的其他进程，系统的缓存和 TLB 肯定会处于与第一个配置文件期间不同的状态。除非您可以确保受控的机器状态，否则不要期望得到一致的结果。

很容易理解为什么每个工具的报告不一致。这两种工具本质上是不同的。 Oprofile 是一个基于采样的分析器，本质上是周期性地中断 CPU。 Gprof 是基于仪器的；它必须编译到您的程序中。这会产生一个与不使用 gprof 时运行的二进制文件不同的二进制文件。因此，gprof 会高估时间。 oprofile 用于 CPU-bound 进程，gprof 用于 I/O-bound 进程。

【讨论】：