奇怪的性能分析器行为：相同的函数，不同的性能表现。

Question

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

如果我先调用one再调用two，结果会相反，two的执行时间比one长。这两个函数是一样的，但第一次调用one的时间总是比第二次调用two的时间短。

为什么呢？

注意：汇编代码完全相同，且代码未启用任何优化。

- arthurprs

---

这些是非常小的差异，可能是由于许多原因造成的。如果你正在学习使用gprof，你应该意识到它的缺点：https://dev59.com/xHI-5IYBdhLWcg3wlpeW#1779343 - Mike Dunlavey

好的文本。非常感谢你 :D - arthurprs

Answer 1

我的猜测是：这可能与mcount数据的解释方式有关。在我的系统上，mcount（monitor.h）的粒度大约为32位长字 - 4个字节。因此，您不应该期望出现这种情况：我从prof和gprof获得了关于完全相同mon.out文件的不同报告。 太阳能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)

- jim mcnamara

---

我忘了提到的一点是：在上述两个报告中，two()和one()所花费的时间是不同的。在一个报告中，这些时间是相等的，而在另一个报告中则不是。 - jim mcnamara

Answer 2

我猜这可能是运行时优化中的一些偶然情况 - 其中一个使用了寄存器而另一个没有，或者像那样的一些小问题。

系统时钟可能以100纳秒的精度运行。 平均调用时间为30纳秒或25纳秒，小于一个时钟周期。 时钟周期的5％的舍入误差非常小。 这两个时间都足够接近于零。

- Michael J

---

汇编代码完全相同，这是我检查的第一件事。我修改了代码以便更多地花时间在函数上，差异确实减少了，但仍然存在。我认为这可能是由于某些CPU行为引起的，例如：分支预测、缓存未命中等。 - arthurprs

Answer 3

第一个被调用的函数总是稍微慢一些吗？如果是这样，我猜测这可能是CPU缓存在起作用，或者是操作系统进行了惰性分页。

顺便问一下：你使用了哪些优化标志来编译代码？

- Evan Teran

---

是的，我猜测这是缓存或类似的东西。没有优化。 - arthurprs