【问题标题】:Strange profiler behavior: same functions, different performances奇怪的分析器行为:相同的功能,不同的性能
【发布时间】:2011-03-03 00:51:21
【问题描述】:

我正在学习使用 gprof,然后我得到了这段代码的奇怪结果:

int one(int a, int b)
{
    int i, r = 0;
    for (i = 0; i < 1000; i++)
    {
        r += b / (a + 1);
    }
    return r;
}

int two(int a, int b)
{
    int i, r = 0;
    for (i = 0; i < 1000; i++)
    {
        r += b / (a + 1);
    }
    return r;
}

int main()
{
    for (int i = 1; i < 50000; i++)
    {
        one(i, i * 2);
        two(i, i * 2);
    }
    return 0;
}

这是分析器的输出

  %   cumulative   self              self     total           
 time   seconds   seconds    calls  us/call  us/call  name    
 50.67      1.14     1.14    49999    22.80    22.80  two(int, int)
 49.33      2.25     1.11    49999    22.20    22.20  one(int, int)

如果我调用一个然后两个结果是相反的,两个比一个花费更多的时间
两者都是相同的功能,但第一次调用总是比第二次花费更少的时间

这是为什么呢?

注意:汇编代码完全相同,并且代码正在编译,没有优化

【问题讨论】:

标签: c++ performance profiler gprof


【解决方案1】:

我的猜测:它是 mcount 数据被解释方式的产物。 mcount (monitor.h) 的粒度大约为 32 位长字 - 在我的系统上为 4 个字节。所以你不会想到这样:我在完全相同的 mon.out 文件上从 prof 和 gprof 得到不同的报告。 太阳能 9 -

prof 
 %Time Seconds Cumsecs  #Calls   msec/call  Name
  46.4    2.35    2.3559999998      0.0000  .div
  34.8    1.76    4.11120000025      0.0000  _mcount
  10.1    0.51    4.62       1    510.      main
   5.3    0.27    4.8929999999      0.0000  one
   3.4    0.17    5.0629999999      0.0000  two
   0.0    0.00    5.06       1      0.      _fpsetsticky
   0.0    0.00    5.06       1      0.      _exithandle
   0.0    0.00    5.06       1      0.      _profil
   0.0    0.00    5.06      20      0.0     _private_exit, _exit
   0.0    0.00    5.06       1      0.      exit
   0.0    0.00    5.06       4      0.      atexit


gprof
   %  cumulative    self              self    total
 time   seconds   seconds    calls  ms/call  ms/call name
 71.4       0.90     0.90        1   900.00   900.00  key_2_text        <cycle 3> [2]
  5.6       0.97     0.07   106889     0.00     0.00  _findbuf [9]
  4.8       1.03     0.06   209587     0.00     0.00  _findiop [11]
  4.0       1.08     0.05                            __do_global_dtors_aux [12]
  2.4       1.11     0.03                            mem_init [13]
  1.6       1.13     0.02   102678     0.00     0.00  _doprnt [3]
  1.6       1.15     0.02                            one [14]
  1.6       1.17     0.02                            two [15]
  0.8       1.18     0.01   414943     0.00     0.00  realloc   <cycle 3> [16]
  0.8       1.19     0.01   102680     0.00     0.00  _textdomain_u     <cycle 3> [21]
  0.8       1.20     0.01   102677     0.00     0.00  get_mem [17]
  0.8       1.21     0.01                            $1 [18]
  0.8       1.22     0.01                            $2 [19]
  0.8       1.23     0.01                            _alloc_profil_buf [22]
  0.8       1.24     0.01                            _mcount (675)

【讨论】:

  • 我没有提到重点是:在两个()和一个()中花费的时间在上面的两个报告中有所不同。在一个时间是相等的,另一个他们不是。
【解决方案2】:

总是第一个调用的速度稍慢吗?如果是这样的话,我猜这是一个 CPU 缓存在做这件事。或者它可能是操作系统的延迟分页。

顺便说一句:编译时使用了哪些优化标志?

【讨论】:

  • 是的,我猜它是缓存或类似的东西。没有优化。
【解决方案3】:

我猜这是运行时优化中的一些侥幸 - 一个使用寄存器,另一个不使用或类似的小东西。

系统时钟的精度可能达到 100 纳秒。平均调用时间 30nsec 或 25nsec 小于一个时钟滴答。时钟刻度的 5% 的舍入误差非常小。两次都接近于零。

【讨论】:

  • 汇编代码完全一样,这是我第一个想到的。我修改了代码以在功能上花费更多时间,差异确实下降了,但仍然存在。我认为这是由一些 cpu 行为引起的,例如:分支预测、缓存未命中等。
猜你喜欢
  • 2015-11-22
  • 1970-01-01
  • 1970-01-01
  • 2014-09-18
  • 1970-01-01
  • 1970-01-01
  • 2018-10-21
  • 2013-11-10
  • 2023-03-03
相关资源
最近更新 更多