Профилировка программ в Linux'е

Для начала определим, что же такое "профилировка программ" и зачем она нужна. Профилировка программ - это процесс определения времени выполнения отдельных элементов программы с целью поиска "бутылочного горлышка".
Книга "Техника оптимизации программ" Криса К., дает еще одно определение профилировки:

Профилировкой мы будем называть измерение производительности как всей программы в целом, так и отдельных ее фрагментов, с целью нахождения "горячих" точек (Hot Spots), — тех участков программы,  на выполнение которых расходуется наибольшее количество времени.

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

gprof

Я начну статью с рассказа о GNU Profiler'е - инструменте "номер один" если вам необходима профилировка. Данная программа входит в состав Gnu Compiler Collection и вам не нужно дополнительно получать ее откуда-то. На всякий случай отмечу, что gprof умеет работать лишь с "результатами труда" компилятора gcc.

В качестве программы, которую я в иллюстративных целях подвергну профилировке, была выбрана flite - это синтезатор английской речи из текста, созданный на основе речевого движка Festival, но при этом крайне упрощенный, чтобы он мог запускаться на КПК под управлением PalmOS или WinCE. Впрочем, этот синтезатор успешно работает и под Линуксом на x86.

Для того, чтобы gprof мог получить необходимую ему информацию из flite нужно скомпилировать последний с ключом -pg. Для этого я, не мудрствуя лукаво, открываю ./config/common_make_rules и в конец секции описания переменных добавляю следующие строчки: Затем, мне остается лишь скомпилировать программу через make. Отмечу, что программа, скомпилированная с ключом -pg, выполняется медленнее, чем программа, скомпилированная без этого ключа - ведь ей нужно еще и записывать отладочную информацию для gprof. Поэтому, если вам захочется измерить время выполнения программы при помощи time, лучше всего это делать используя тот исполняемый файл, что был скомпилирован без ключа -pg.

Теперь, чтобы собрать отладочную информацию, нужно запустить программу как вы это обычно делаете. После успешного завершения работы (не через abort()!) в рабочем каталоге программы (том каталоге, куда программа в последний раз делала chdir()) будет лежать файл gmon.out с отладочной информацией. Чтобы получить из него результаты профилировки нужно запустить gprof: gprof [имя_исполняемого файла [файл_с_отладочной информацией]]

gprof ./flite gmon.out

Прежде чем я приступлю к рассмотрению отчета профилировщика, надо сказать пару слов о погрешностях, появление которых неизбежно в его результатах. Наблюдение за программой происходит не постоянно, а в течение множества отсчетов с определенным периодом, величина которого обычно указывается в самом начале вывода gprof. Как следствие, время работы функции, например, если оно достаточно мало по сравнению с периодом отсчета, может быть неточным и меняться с каждой попыткой профилирования. Все что мы можем судить о функции в этом случае - то что она выполняется достаточно малое время, чтобы о ней беспокоиться.
Повысить точность можно двумя путями. Во-первых, можно загрузить программу большим набором входных данных, чтобы она поработала побольше и собрала больше статистики. А во-вторых, можно собрать и обработать вместе данные нескольких запусков профайлера. В нашем случае, это можно сделать примерно вот таким однострочником (в файле english.txt содержится 2324 английских слова - текст из английской вики про FPGA):

ITERATIONS=10 && ./flite ../english.txt ~/test.wav && mv gmon.out gmon.sum && i=1 && while [ "$i" -le "$ITERATIONS"  ]; do echo "$i iteration..." && ./flite ../english.txt ~/test.wav && gprof -s ./flite gmon.out gmon.sum && i=$((i+1)); done

Здесь выполняется всего 11 итераций, думаю этого достаточно, чтобы получить относительно точный результат (относительно одной итерации). Посмотреть результаты можно почти так же как и прежде: gprof ./flite gmon.sum.

Теперь, наконец-то перейдем к рассмотрению сгенерированного отчета. Весь отчет, вместе со встроенной справкой, занимает около трех тысяч строк, поэтому я приведу его исключительно для ознакомления, а рассмотрены будут лишь наиболее примечательные части.
 Первым в отчете gprof идет так называемый "простой" профиль (flat profile), который показывает сколько времени какая функция программы выполнялась. Первыми в этом списке идут функции, на выполнение которых было затрачено больше всего времени работы программы.
Но стоит учитывать, что "долго выполняться" можно по-разному: функция может быть вызванной всего несколько раз за все время работы программы, но она будет выполняться действительно долго. Или же эта функция может выполняться всего за долю миллисекунды, но при этом она вызывается сотни тысяч раз. Тем не менее, результат один - и там и там мы имеем потерю производительности.

Как видно из вышеприведенного отчета, у нас есть две таких "тяжеловесных" функции. Первая - lpc_resynth_fixedpoint(), за 11 прогонов программы вызывается всего 869 раз (примерно 79 вызовов на один запуск ./flite), но и работает она долго по сравнению с другими функциями - по 0.01 секунду на каждый запуск (self s/call - время работы функции без учета вызываемых ею подпрограмм, total s/call - с учетом вызываемых подпрограмм) и таким образом за все время работы программы (помноженное на количество тестовых прогонов) она "съедает" 6.14 секунд.
Вторая функция: internal_ff(), отрабатывает за ничтожно малое время (как видно gprof даже не успел подсчитать время работы функции - стоят нули в self\total s/call). Но за тестовые прогоны эта функция успевает "съесть" 2.02 секунды времени работы программы, а все потому что она вызывается аж 5176457 раз!

Итак, у нас есть функции, которые больше всех "тормозят" работу программы. Можно попытаться их как-нибудь оптимизировать, но перед этим может оказаться полезным посмотреть на граф вызовов этих функций. Данный граф, в виде таблицы, приведен во второй части отчета gprof. Я же покажу лишь те его части, что относятся к рассмотренным нами ранее, "тяжеловесным" функциям. Граф вызовов показывает какая функция какую функцию вызывала вместе с дополнительными данными в виде времени выполнения и тому подобными вещами.

Каждой из функций отведен отдельный раздел в таблице вызовов. В этом разделе расположена запись о самой функции - это строка, где указан номер в столбце index. Этот номер является индексным номером функции; поскольку каждая функция в графе вызовов отмечена своим уникальным номером и все функции упорядочены по возрастанию номеров, то ориентироваться в таблице графа вызовов достаточно просто.

Над строкой с записью о функции перечисляются функции, которые вызывают данную функцию. Так например, lpc_resynth_fixedpoint() вызывается из функции join_units_modified_lpc(). А функция internal_ff() вызывается из функций ffeature() и path_to_item().

Под строкой же с записью о рассматриваемой функции перечислены функции, которые вызываются из нее. Для lpc_resynth_fixedpoint() это cst_safe_alloc(), cst_wave_resize() и другие.

Отдельно, следует сказать об, уже возможно привлекшем внимание, обозначении: internal_ff [12]. Подобным образом в gprof'е описываются взаимно-рекурсивные функции, коей по-видимому и является internal_ff().
Ведь, если одна функция вызывает другую, а то, в свою очередь, снова вызывает первую, то трудно определить как же следует считать для первой функции время проведенное внутри дочерних функций. Следует ли для первой функции считать время, которое тратится внутри второй функции на исполнение первой функции, ведь формально функция номер два все еще выполняется?
Чтобы не мучиться вопросом кто же первее - курица или яйцо, разработчики gprof стали объединять подобные функции в циклы. Одному из таких циклов - циклу №2 и принадлежит функция internal_ff().
Далее, в отчете gprof'а должна встретиться запись посвященная исключительно циклу №2 (<cycle 2>), для которого уже возможно подсчитать время, проведенное внутри дочерних функций (это просто все функции цикла).

Тем, кто хочет узнать о gprof подробнее, советую ссылку на документацию с опеннета: http://www.opennet.ru/docs/RUS/gprof/gprof.html

Итак, вот мы и получили пару функций - кандидатов на оптимизацию. Их длинным исходным кодом можно насладиться вот здесь. Отмечу лишь пару моментов. Во-первых, помимо функции lpc_resynth_fixedpoint() есть такая же, но для чисел с плавающей точкой. Поскольку flite будет запускаться на микроконтроллере, где нет FPU, использование функции для чисел с плавающей точкой запросто может еще больше замедлить работу программы. Поэтому, я продолжу рассматривать функцию, рассчитанную на работу без чисел с плавающей точкой.
Во-вторых, как уже понятно код функций слишком большой, чтобы сходу в нем разобраться и что-то оптимизировать. Поэтому, возможно имеет смысл использование других инструментов, которые способны залезть глубже, чем на уровень одних лишь функций.

gcov

GNU Coverage Testing Tool - как раз один из подобных инструментов. С его помощью можно получить так называемый, аннотированный исходный код, в котором напротив каждой строки будет написано сколько раз она выполнялась.
Стоит отметить, что числа приводимые gcov опять таки не являют собой образец точности и эталона. Связано это с тем, что несколько строчек кода на Си могут быть заоптимизированы компилятором отнюдь не в столько же соответствующих машинных команд. Приведу прямую цитату из man'а по gcov:

For example, code like this:

               if (a != b)
                 c = 1;
               else
                 c = 0;

can be compiled into one instruction on some machines.  In this case,
there is no way for gcov to calculate separate execution counts for
each line because there isn't separate code for each line.  Hence the
gcov output looks like this if you compiled the program with
optimization:

               100:   12:if (a != b)
               100:   13:  c = 1;
               100:   14:else
               100:   15:  c = 0;

The output shows that this block of code, combined by optimization,
executed 100 times.  In one sense this result is correct, because there
was only one instruction representing all four of these lines.
However, the output does not indicate how many times the result was 0 and how many times the result was 1.

Чтобы иметь возможность использовать gcov, нужно опять таки особым образом скомпилировать программу, которую необходимо профилировать. На этот раз необходимо использовать ключи -fprofile-arcs -ftest-coverage. Для все той же программы flite необходимо добавить следующую пару строчек в конец секции с переменными в файле ./config/common_make_rules:
После компиляции программы в каталоге с объектными файлами будут лежать и рабочие файлы gcov с расширением gcno.
Но этих файлов недостаточно для построения аннотированных исходников - ведь нужно еще собрать и статистику - сколько строк сколько раз выполнялись. Для этого нужно запустить профилируемую программу как обычно:

./flite ../english.txt ~/test.wav

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

Теперь можно приступать к получение аннотированного исходного кода. В самом простом случае достаточно просто вызвать gcov и он сам все сгенерирует. Но это будет работать лишь в том случае, когда и объектные файлы, и исходные, и сгенерированные gcov'ом будут расположены в одном каталоге. Если же, как в случае с flite все будет раскидано по разным каталогам, то следует поступать несколько иначе.
Необходимо запускать gcov в каталоге с обрабатываемым исходным файлом и передать ему с опцией -o путь к каталогу с соответствующими объектными файлами и файлами от gcov. Только тогда мы получим аннотированный исходный код.
Аннотированные исходники для рассмотренных ранее функций выглядят вот так: https://gist.github.com/1594692. Число напротив строки показывает сколько раз данная строка исполнялась. Если вместо числа стоит символ "-", то значит данная строка не является исполняемой (комментарий, объявление переменной), а если стоят символы "#", то данная строка не выполнялась ни разу.

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

На этом я заканчиваю свой маленький обзор средств профилирования программ под Linux, оставляя за бортом такие утилиты как Google Performance Tools, Valgrind и прочие...