Странное поведение профайлера: одни и те же функции, разная производительность

Я учился использовать 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
person arthurprs    schedule 12.06.2010    source источник
comment
Это очень небольшие различия, и они могут быть связаны с чем угодно. Если вы учитесь использовать gprof, вы должны знать о его недостатках: stackoverflow.com/questions/1777556/alternatives-to-gprof/   -  person Mike Dunlavey    schedule 13.06.2010
comment
Хороший текст. Большое спасибо: D   -  person arthurprs    schedule 13.06.2010

Ответы (3)


arrow_upward
1
arrow_downward

Я предполагаю, что это какая-то случайность в оптимизации времени выполнения - один использует регистр, а другой - нет, или что-то в этом роде.

Системные часы, вероятно, работают с точностью до 100 нс. Среднее время вызова 30 нс или 25 нс меньше одного такта часов. Ошибка округления в 5% тактового импульса довольно мала. Оба времени достаточно близки к нулю.

person Michael J    schedule 12.06.2010
comment
Ассемблерный код точно такой же, это первое, что мне показалось. Я изменил код, чтобы тратить больше времени на функции, и разница действительно уменьшилась, но все еще существует. Я думаю, что это вызвано некоторым поведением процессора, таким как: прогнозирование ветки, промахи кеша и т. Д. - person arthurprs; 12.06.2010

arrow_upward
1
arrow_downward

Мое предположение: это артефакт того, как интерпретируются данные 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)
person jim mcnamara    schedule 12.06.2010
comment
Я не упомянул, что суть была в том, что время, затраченное на two() и one(), различается в двух вышеприведенных отчетах. В одном времена равны, в другом нет. - person jim mcnamara; 12.06.2010

arrow_upward
0
arrow_downward

Всегда ли вызывается первый, который немного медленнее? Если это так, я бы предположил, что это кеш процессора делает свое дело. или это может быть ленивая подкачка операционной системой.

Кстати: с какими флагами оптимизации компилируются?

person Evan Teran    schedule 12.06.2010
comment
Да, я думаю, это кеш или что-то в этом роде. Никаких оптимизаций. - person arthurprs; 12.06.2010