Замеры времени и профилирование
Используйте профилировщик.
Не считая такого надежного и достоверного способа, как замер времени исполнения программы, самым важным инструментом для анализа производительности является система для генерации профилей. Профиль (profile) – это измерение того, где именно программа "тратит время". Некоторые профили предоставляют список всех функций, количество вызовов каждой из них и долю потребляемого каждой функцией времени от общего времени исполнения программы. Другие показывают, сколько раз было выполнено каждое выражение. Выражения, которые выполняются часто, сильнее влияют на время исполнения, а те, которые не выполняются никогда, скорее всего, являются бесполезным или неадекватно оттестированным кодом.
Профилирование – эффективный способ поиска горячих точек (hot spots), или критических мест программы, то есть функций фрагментов кода, которые расходуют львиную долю всего времени исполнения программы. Однако же интерпретировать результаты профилирования надо с достаточной степенью осторожности. Из-за изощренности компиляторов, сложности организации кэширования и работы с памятью, а также из-за того, что сам процесс профилирования влияет на производительность, статистические показатели в профилях могут быть только приблизительными.
В 1971 году в работе, где впервые был представлен термин "профилирование", Дон Кнут написал, что, "как правило, менее 4% программы поглощают более половины от всего времени исполнения". Принимая во внимание это замечание, можно сделать вывод о способах применения профилирования: с его помощью определяются участки программы, поглощающие большую часть времени работы, в них вносятся улучшения, и процесс повторяется еще раз для поиска новых критических мест. Выясняется, что после одной-двух подобных итераций характерных "горячих точек" не остается.
Профилирование обычно включается специальным флагом или опцией компилятора. Программа выполняется, и после этого показываются результаты работы профилировщика. В Unix таким флагом является, как правило, – р, а профилировщик называется prof:
В приводимой далее таблице показан профиль, сгенерированный рабочей версией спам-фильтра, которую мы создали специально для того, чтобы разобраться в его поведении. В ней используется фиксированное сообщение и фиксированный набор из 217 фраз, который сравнивается с сообщением 10 000 раз. Запуск производился на машине MIPS R10000 250 MHz; использовалась изначальная версия strstr – с вызовами других стандартных функций. Результаты были переформатированы для более удачного размещения на странице. Обратите внимание на то, что размер ввода (217 фраз) и количество запусков (10 000) можно использовать для проверки правильности работы – эти числа появляются в колонке "calls" (вызовы), в которой показано количество вызовов каждой функции.
12234768552: Total number of instructions executed 13961810001: Total computed cycles 55.847: Total computed execution time (sees.) 1.141: Average cycles / instruction
| secs | % | cum% | cycles | instructions | calls | function |
|---|---|---|---|---|---|---|
| 45.260 | 81.0 | 81.0 | 11314990000 | 9440110000 | 48350000 | strchr |
| 6.081 | 10.9 | 91.9 | 1520280000 | 1566460000 | 46180000 | strncmp |
| 2.592 | 4.6 | 96.6 | 648080000 | 854500000 | 2170000 | strstr |
| 1.825 | 3.3 | 99.8 | 456225559 | 344882213 | 2170435 | strlen |
| 0.088 | 0.2 | 100.0 | 21950000 | 28510000 | 10000 | isspam |
| 0.000 | 0.0 | 100.0 | 100025 | 100028 | 1 | main |
| 0.000 | 0.0 | 100.0 | 53677 | 70268 | 219 | memccpy |
| 0.000 | 0.0 | 100.0 | 48888 | 46403 | 217 | memcmp |
| 0.000 | 0.0 | 100.0 | 17989 | 19894 | 219 | isspam |
| 0.000 | 0.0 | 100.0 | 16798 | 17547 | 230 | strlen |
| 0.000 | 0.0 | 100.0 | 10305 | 10900 | 204 | realfree |
| 0.000 | 0.0 | 100.0 | 6293 | 7161 | 217 | estrdup |
| 0.000 | 0.0 | 100.0 | 6032 | 8575 | 231 | cleanfree |
| 0.000 | 0.0 | 100.0 | 5932 | 5729 | 1 | readpat |
| 0.000 | 0.0 | 100.0 | 5899 | 6339 | 219 | getline |
| 0.000 | 0.0 | 100.0 | 5500 | 5720 | 220 | malloc |