Замеры времени и профилирование
Автоматизируйте замеры времени. В большинстве систем существуют команды, позволяющие выяснить, сколько времени работала программа. В Unix такая команда называется time:
Эта команда запускает программу и возвращает три числа, означающих время
в секундах: время real — физическое время, израсходованное до завершения
работы программы; время user — время процессора, потраченное на исполнение
самой программы; время sys — время, потраченное на программу операционной
системой. Если в вашей системе есть аналогичная команда, используйте ее
— числа будут более информативными и надежными, и делать отсчеты будет
проще, чем при использовании секундомера. Ведите подробные записи. При
работе над программой — внесении модификаций и/или проведении измерений
-т у вас накопится огромное количество данных, в которых вам будет трудно
разобраться по памяти уже через день-два. (Какая именно версия работает
на 20 % быстрее?) Многие технологии, которые мы обсуждали в главе о тестировании,
могут быть адаптированы и к измерениям времени и улучшению производительности.
Используйте компьютер для запуска набора тестов и измерения времени их работы, а самое главное — используйте регрессивное тестирование, чтобы удостовериться в том, что "улучшения" производительности не нарушили корректности программы.
Если в вашей системе нет команды time или вы хотите замерить время работы отдельно взятой функции, не так трудно создать себе оснастку для таких замеров — по аналогии с тестовой оснасткой. В С и C++ существует стандартная функция clock, которая сообщает, сколько процессорного времени программа использовала до текущего момента. Ее можно вызвать перед интересующей вас функцией и после нее и таким образом вычислить время ее исполнения процессором:
Масштабирующий коэффициент CLOCKS_PEfi_SEC характеризует разрешение таймера,
возвращаемое clock. Если функция выполняется за доли секунды, запустите
ее в цикле, но (если измерения должны быть особо точными) не забудьте
компенсировать затраты времени на сам цикл:
В Java функции класса Date выдают текущее системное время, которое приблизительно
равно времени, использованному процессором:
Значение, возвращаемое getTime, измеряется в миллисекундах.
Используйте профилировщик. Не считая такого надежного и достоверного способа, как замер времени исполнения программы, самым важным инструментом для анализа производительности является система для генерации профилей. Профиль (profile) -- это измерение того,,где именно программа "тратит время". Некоторые профили предоставляют список всех функций, количество вызовов каждой из них и долю потребляемого каждой функцией времени от общего времени исполнения программы. Другие показывают, сколько раз было выполнено каждое выражение. Выражения, которые выполняются часто, сильнее влияют на время исполнения, а те, которые не выполняются никогда, скорее всего, являются бесполезным или неадекватно оттестированным кодом.
Профилирование — эффективный способ поиска горячих точек (hot spots), или критических мест программы, то есть функций ши^фрагмен-тов кода, которые расходуют львиную долю всего времени исполнения программы. Однако же интерпретировать результаты профилирования надо с достаточной степенью осторожности. Из-за изощренности компиляторов, сложности организации кэширования и работы с памятью, а также из-за того, что сам процесс профилирования влияет на производительность, статистические показатели в профилях могут быть только приблизительными.
В 1971 году в работе, где впервые был представлен термин "профилирование", Дон Кнут написал, что, "как правило,-менее 4 % программы поглощают более половины от всего времени исполнения". Принимая во внимание это замечание, можно сделать вывод о способах применения профилирования: с его помощью определяются участки программы, поглощающие большую часть времени работы, в них вносятся улучшения, и процесс повторяется еще раз для поиска новых критических мест. Выясняется, что после одной-двух подобных итераций характерных "горячих точек" не остается.
Профилирование обычно включается специальным флагом или опцией компилятора. Программа выполняется, и после этого показываются результаты работы профилировщика. В Unix таким флагом является, как правило, -р, а профилировщик называется prof:
В приводимой далее таблице показан профиль, сгенерированный рабочей версией
спам-фильтра, которую мы создали специально для того, чтобы разобраться
в его поведении. В ней используется фиксированное сообщение и фиксированный
набор из 217 фраз, который сравнивается с сообщением 10 000 раз. Запуск
производился на машине MIPS R10000 250 MHz; использовалась изначальная
версия st rst r — с вызовами других стандартных функций. Результаты были
переформатированы для более удачного размещения на странице. Обратите
внимание на то, что размер ввода (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 |
Очевидно, что в затратах времени доминируют две функции: strchr и strncmp, причем обе вызываются из strstr. Итак, Кнут ориентирует нас правильно: небольшая часть программы поглощает большую часть времени ее исполнения. При первом профилировании программы очень часто выясняется, что лидирующие в профиле две-три функции поглощают половину времени и более, как в приведенном случае, и, соответственно, становится сразу же ясно, на чем сконцентрировать внимание.
Концентрируйтесь на критических местах. Переписав st rst r, мы еще раз выполнили профилирование для spamtest и выяснили, что теперь 99.8 % времени тратит собственно strstr, хотя в целом программа и стала работать быстрее. Когда одна функция является таким явным узким местом программы, существует только два способа исправить положение: улучшить саму функцию, применив более эффективный алгоритм, или/ке избавиться от этой функции вообще, переписав всю программу.
Мы выбрали второй способ — переписали программу. Ниже приведены первые несколько строк профиля работы программы sparest, использующей последнюю, наиболее быструю реализацию isspam. При этом общее время работы программы существенно уменьшилось, критической точкой стала функция memcmp, a isspam стала заш'мать более существенную долю от общего времени. Эта версия гораздо сложнее предыдущей, однако эта сложность окупается с лихвой благодаря отказу от использования strlen и strchr в isspam и замене sees % cum% cycles instructions calls function strncmp на memcmp, которая тратит меньше усилий и» обработку каждого байта.
| secs | % | cum% | cycles | instructions | calls | function |
| 3.524 | 56.9 | 56.9 | 880890000 | 1027590000 | 46180000 | memcmp |
| 2.662 | 43.0 | 100.0 | 665550000 | 902920000 | 10000 | isspam |
| 0.001 | 0.0 | 100.0 | 140304 | 106043 | 652 | strlen |
| 0.000 | 0.0 | 100.0 | 100025 | 100028 | 1 | main |
Весьма поучительно будет потратить некоторое время на сравнение счетчиков циклов и количества вызовов различных функций в двух профилях. Отметьте, что количество" вызовов strlen упало от нескольких миллионов до 652, a strncmp и memcmp вызываются одинаковое количество раз. Обратите внимание и на то, что isspam, которая сейчас взяла на себя и функцию st rch r, умудряется обойтись гораздо меньшим количеством циклов благодаря тому, что она проверяет на каждом шаге только нужные образцы. Изучение чисел может раскрыть и многие другие детали хода выполнения программы.
"Горячая точка" нередко может быть уничтожена или, по крайней мере, существенно "охлаждена" гораздо более простыми способами, чем мы применили для спам-фильтра. Когда-то давным-давно профилирование Awk показало, что одна функция вызывается примерно миллион раз — в таком цикле:
? for (j ='i; j < MAXFLD; j++)
? clear(j);
Выполнение этого цикла, в котором поля очищались перед считыванИем каждой новой строки ввода, занимало почти 50 % от всего времени исполнения. Константа MAXFLD — максимальное количество полей в строке ввода — была равна 200. Однако в большинстве случаев использования Awk реальное количество полей не превышало двух-трех. Таким образом, огромное количество времени тратилось на очистку полей, которые никогда и не устанавливались. Замена константы на предыдущее значение максимального количества полей дало выигрыш в скорости 25 %. Все исправления свелись к изменению верхней границы цикла:
for (j = i; j < rnaxfld; j++)
clear(j);
maxfld = i;
Постройте график. Особенно удачным получается представление замеров производительности в виде графиков. Графики помогут более наглядно представить информацию о влиянии изменения параметров, сравнить алгоритмы и структуры данных, а иногда и указать на неожиданное поведение программы. Графики длин цепочек для нескольких хэш-мультипликаторов в главе 5 явно продемонстрировали преимущества одних мультипликаторов перед другими.
На представленном ниже графике показано влияние размера массива хэш-таблицы на время исполнения С-версии программы ma rkov; в качестве вводимого текста использовались Псалмы (42 685 слов, 22 482 префикса)., Мы поставили два эксперимента. В первой серии запусков программа использовала размеры массивов, которые являлись степенями двойки — от 2 до 16 384; в другой версии использовались размеры, которые являлись максимальным простым числом, меньшим каждой степени двойки. Мы хотели посмотреть, приведет ли использование простых чисел в качестве размеров массивов к ощутимой разнице в производительности.
На графике ясно видно, что время исполнения для такого ввода не зависит
от размера таблицы при размерах, больших 10 000 элементов; также нет и
существенной разницы между использованием в качестве размеров таблицы
степеней двойки или простых чисел.
Упражнение 7-2
Вне зависимости от того, есть на вашей машине команда time или нет, используйте clock или getTime для создания собственного измерителя времени. Сравните его результаты с системным временем. Как влияет на результаты другая активность на машине?
Упражнение 7-3
В первом профиле st rch г вызывалась 48 350 000 раз, a st rncmp — только 46 180 000 раз. Объясните это различие.
|