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

Question

я учась использовать дргоЕ, а затем я получил странные результаты по этому коду:

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) 

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

Почему?

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

Answer 1

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

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

Answer 2

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

BTW: какие флаги оптимизации скомпилированы?

Answer 3

Мое предположение: это артефакт, по которому интерпретируются данные 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)