Странное поведение профилировщика: одинаковые функции, разные характеристики - PullRequest
Новая
       16

Странное поведение профилировщика: одинаковые функции, разные характеристики

3 голосов
/ 12 июня 2010

Я учился использовать 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)

Если я вызову один, то дварезультат обратный, два занимает больше времени, чем один
обе функции одинаковы, но первый вызов всегда занимает меньше времени, чем второй

Почему это так?

Примечание:код сборки точно такой же, и код компилируется без оптимизации

Ответы [ 3 ]

1 голос
/ 12 июня 2010

Мое предположение: это артефакт интерпретации данных mcount.Детализация для mcount (monitor.h) составляет порядка 32-битного длинного слова - 4 байта в моей системе.Так что вы не ожидаете этого: я получаю разные отчеты от prof vs 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)
1 голос
/ 12 июня 2010

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

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

0 голосов
/ 12 июня 2010

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

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

...