3

我正在学习使用 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)

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

这是为什么？

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

4

3 回答 3

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)
于 2010-06-12T19:16:37.353 回答
1

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

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

于 2010-06-12T16:06:52.010 回答
0

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

顺便说一句：正在编译哪些优化标志？

于 2010-06-12T16:27:10.430 回答