Рассмотрим типичную ситуацию — приходит пользователь и говорит «я делаю в приложении то-то и то-то и у меня все сильно тормозит». Как понять, в чем проблема, и исправить ее? Вот об этом мы и поговорим в данной заметке. Приведенный список методов не претендует на полноту , однако это то, что в настоящее время я чаще всего использую на практике. Несмотря на то, что пишу я сейчас в основном на C, описанные методы будут также применимы в проектах, использующих С++, и, возможно, другие языки программирования.
Дедовский метод
Начнем с самого примитивного, но, тем не менее, весьма популярного способа. Идея простая — замеряем время в начале выполнения операции, замеряем в конце, считаем дельту, выводим в лог. Вот так это примерно выглядит с использованием процедуры gettimeofday:
/* … */
struct timeval tv ;
gettimeofday ( & tv , NULL ) ;
double time_begin = ( ( double ) tv. tv_sec ) * 1000 +
( ( double ) tv. tv_usec ) / 1000 ;
/* … */
gettimeofday ( & tv , NULL ) ;
double time_end = ( ( double ) tv. tv_sec ) * 1000 +
( ( double ) tv. tv_usec ) / 1000 ;
double total_time_ms = time_end — time_begin ;
printf ( «TOTAL TIME (ms) = %f n » , total_time_ms ) ;
Примечание: См также кроссплатформенную реализацию процедуры getCurrentTimeMs из заметки Продолжаем изучение OpenGL: простой вывод текста .
Пропарсить полученный лог можно, к примеру, с использованием Perl :
‘ (ms) = (.*?),/; if($1 > 1.5) { print «$_»; } $max = $1 if $1 > ‘
‘$max; } print «max = $maxn»; ‘
Несмотря на тупость метода, он очень удобен, например, когда в приложении что-то тормозит иногда , а не постоянно. При использовании метода нужно помнить, что системный вызов gettimeofday сам по себе сравнительно дорогой. Если использовать его, скажем, между захватом и освобождения спинлока, бутылочное горлышко, которое вы ищите, может уехать вообще в другое место. Также вы можете получать неправильные цифры, если между двумя замерами времени шедулер решит переключиться на выполнение другого процесса.
Утилиты strace и ltrace
Программа strace показывает системные вызовы и их возвраты, что бывает довольно удобно при отладке. С флагом -c она показывает топ системных вызовов, их количество, и сколько времени было проведено в вызове:
/home/ubuntu
% time seconds usecs/call calls errors syscall
—— ———— ———— ——— ——— —————-
31.73 0.000132 15 9 mmap
19.95 0.000083 28 3 3 access
11.30 0.000047 16 3 open
10.58 0.000044 22 2 munmap
8.17 0.000034 9 4 mprotect
4.57 0.000019 5 4 fstat
3.37 0.000014 3 5 close
2.88 0.000012 12 1 write
2.64 0.000011 4 3 brk
1.68 0.000007 7 1 execve
1.44 0.000006 6 1 read
0.96 0.000004 4 1 getcwd
0.72 0.000003 3 1 arch_prctl
—— ———— ———— ——— ——— —————-
100.00 0.000416 38 3 total
Программа ltrace делает то же самое и для библиотечных вызовов:
/home/ubuntu
% time seconds usecs/call calls function
—— ———— ———— ——— ———————
17.31 0.000636 636 1 setlocale
12.93 0.000475 118 4 __freading
9.71 0.000357 178 2 fclose
8.11 0.000298 298 1 puts
6.56 0.000241 120 2 fileno
5.69 0.000209 209 1 getenv
5.61 0.000206 103 2 fflush
5.52 0.000203 203 1 strrchr
5.36 0.000197 98 2 __fpending
5.25 0.000193 193 1 __cxa_atexit
4.24 0.000156 156 1 bindtextdomain
4.16 0.000153 153 1 textdomain
3.86 0.000142 142 1 getcwd
2.94 0.000108 108 1 getopt_long
2.75 0.000101 101 1 free
—— ———— ———— ——— ———————
100.00 0.003675 22 total
Чтобы подключиться при помощи strace или ltrace к уже работающему процессу, используйте флаг -p .
Во FreeBSD утилита, аналогичная strace, называется truss. Кроме того, strace и ltrace доступны в портах.
Использование gprof
Утилита gprof доступна как в Linux, так и во FreeBSD. Для примера попробуем прогнать ее на программе из заметки Реализация хэш-таблиц, почти как в Perl .
Если программа уже была собрана, делаем make clean . Затем пересобираем ее с флагом -pg :
Запускаем программу без gprof:
Будет создан двоичный файл gmon.out. Этот шаг обязателен, иначе при попытке профайлинга увидим ошибку:
Теперь запускаем программу под gprof:
При этом сама программа в stdout ничего выводить не будет. Полученный текстовый файл profile вполне читаемый — видно, где и сколько времени проводила программа. Так, к примеру, могут выглядеть первые несколько его строк:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ns/call ns/call name
30.37 0.10 0.10 475254 210.86 295.21 htable_del
18.22 0.16 0.06 1425762 42.17 42.17 _htable_hash
18.22 0.22 0.06 475254 126.52 210.86 htable_set
12.15 0.26 0.04 950508 42.17 42.17 _htable_resize
12.15 0.30 0.04 475254 84.34 126.52 htable_get
3.04 0.31 0.01 main
0.00 0.31 0.00 1 0.00 0.00 htable_free
0.00 0.31 0.00 1 0.00 0.00 htable_new
Также можно построить красивый граф вызовов:
sudo pip install gprof2dot
gprof2dot . / profile | dot -Tsvg -o output.svg
Пример полученной картинки (кликабельно, SVG, ~ 9 Кб):
Подробности про утилиту dot и Graphviz см в заметке Рисуем красивые графы при помощи Graphviz .
Получение стэктрейсов при помощи Gdb
Как ни странно, gdb можно использовать и для профайлинга. Просто говорим:
… где в gdb.script написано:
Понятно, что таким образом можно собирать не только стэктрейсы, но и другую информацию, например, значения переменных, переданных аргументов, и так далее. Этот прием показал себя весьма полезным, например, при поиске и устранении lock contention. Если программа часто висит в ожидании лока, мы будем видеть это ожидание по стэктрейсам.
Профайлинг при помощи perf top
Установка perf в Ubuntu / Debian:
При первом запуске увидим что-то вроде:
WARNING: perf not found for kernel 3.13.0-71
You may need to install the following packages for this
specific kernel:
linux-tools-3.13.0-71-generic
linux-cloud-tools-3.13.0-71-generic
You may also want to install one of the following packages to keep
up to date:
linux-tools-generic
linux-cloud-tools-generic
Ставим и эти пакеты тоже:
Можно посмотреть top по всей системе:
… по процессам конкретного пользователя:
… или конкретному процессу:
Вот как это примерно выглядит:
Картинка обновляется в реальном времени. При помощи стрелочек и клавиши Enter можно «проваливаться внутрь» процессов и функций, вплоть до подсвечивания строчек кода и ассемблерных инструкций , которые тормозят. Очень удобно!
Во FreeBSD, насколько я понимаю, аналогичный функционал предоставляется программой pmcstat . Однако на практике я ею пока не пользовался.
Строим флемграфы
Помимо отображения топа самых часто вызываемых процедур программа perf умеет много чего еще.
Например, пишем stack samples с частотой 99 Герц для определенного pid’а со сборкой данных о call chains (флаг -g ):
Запуск конкретной программы под perf производится так:
На выходе получаем файл perf.data.
Смотрим отчет:
Но читать его в таком виде не очень-то удобно. Намного удобнее построить флеймграф:
sudo perf script | . / FlameGraph / stackcollapse-perf.pl > out.perf-folded
. / FlameGraph / flamegraph.pl out.perf-folded > perf.svg
Получаем красивую картинку вроде такой :
В полученном SVG-файле можно кликать на названия процедур для увеличения соответствующего участка флеймграфа, а также искать процедуры по имени. Здесь и здесь можно найти больше информации и примеров. Еще этот набор скриптов умеет работать с dtrace и строить разные другие виды флеймграфов, но это уже тема для отдельной заметки.
Дополнение: Описание того, как строятся флеймграфы при помощи DTrace, вы найдете в заметке Использование DTrace на примере FreeBSD и Linux . Аналогичную инструкцию для SystemTap вы найдете в посте Установка и простые примеры использования SystemTap , а для bcc/eBPF — в статье Трассировка и профайлинг в Linux с помощью bcc/eBPF . Если же вас интересует профилирование памяти, читайте заметку Профилируем использование памяти в программах на C/C++ при помощи Heaptrack .
Заключение
Как видите, недостатка в инструментах профайлинга в мире C/C++ не наблюдается. Не один из описанных приемов не является универсальным, но при правильном их комбинировании можно разобраться практически в любой проблеме.
