Иногда возникает необходимость заглянуть внутрь программы, что-бы посмотреть почему она «так тормозит». Естественно начинается все с высокоуровневых средств htop/atop/nettop/iotop/sar. Но если они показывают, что производительность упирается в процессор, то необходимо знать какие функции требуют больше всего вычислительных мощностей. Это может помочь как переписать свою программу для провышения производительности, так и подобрать оптимальные настройки для чужой.
Собственно функция профилировщика — найти узкие места в программе и выдать нам как можно больше информации о том куда уходят процессорные такты. Можно выделить три основных модели профилирования:
Гарантированное профилирование (determine — не нашел как перевести это лучше). Целевая программа модифицируется (чаще всего перекомпилируется с определенными флагами — -pg для gcc). — в код внедряются вызовы библиотеки профилирования, собирающие информацию о выполняемой программе и передающие ее профилировщику. Наиболее часто замеряется время выполнения каждой функции и после тестового прогона программы можно увидеть вывод, подобный следующему:
% cumulative self self total
time seconds seconds calls ms/call ms/call name
33.34 0.02 0.02 7208 0.00 0.00 open
16.67 0.03 0.01 244 0.04 0.12 offtime
16.67 0.04 0.01 8 1.25 1.25 memccpy
16.67 0.05 0.01 7 1.43 1.43 write
Очевидным минусом гарантированного профилирования является необходимость перекомпиляции программы, что неудобно, а иногда и невозможно (если это не ваша программа, например). Также гарантированное профилирование значительно влияет на скорость исполнения программы, делая получение коректного времени исполнения затруднительным. Типичный представитель — gprof,
Статистическое профилирование (statistic profiling) — исполнение программы периодически (~100-1000 раз в секунду) останавливается, управление передается профилировщику, который анализирует текущий констекст исполнения. Затем, используя отладочную информацию или таблици символов из исполняемого файла программы и загруженных библиотек, определяется исполняемая в текущий момент функция и, если возможно, последовательность вызовов в стеке. Профилировщик увеличивает счетчик попаданий для активной функции, а после окончания профилирования можно увидеть сколько раз программа «была поймана» на исполнении определенных функций. Идея очень простая — если в некоторой функции A программа проводит в два раза больше времени, чем в функции B, то в среднем ( при достаточно длительном исполнении) мы будем в два раза чаще останавливаться внутри A, чем внутри B. Статистическое профилирование не требует перекомпиляции программы (хотя некоторые флаги компилятора могут помочь восстанавливать стек), значительно меньше гарантированного профилирования влияет на время и тайминги исполнения, но требует длительного или многократного прогона программы что бы получить надежные результаты. Типичный представитель — oprofile.
Профилирование на эмуляторе . Идея состоит в написании эмулятора, очень точно воспроизводящего целевой процессор, включая кеши со всеми механизмами замещения, декодировщики инструкций, конвееров и прочего. В общем случае задача похожа на не решаемую, учитываю сложность современных процессоров и огромное количество факторов, влияющих на производительность. Кроме этого профилирования на эмуляторе может занимать ооочень много времени из за накладных расходов на эмуляцию. Едиственный известный мне представитель/попытка — valgrind, хотя VTune от intel частично использует подобную технику для анализа кода.
По сумме характеристик статистическое профилирование является самым интересным (IMHO), посколько достаточно просто реализуется, практически не влияет на исполнение программы, способно профилировать даже те компоненты, для которых нет исходных текстов (например внешние библиотеки, линкуемые бинарно или с помощую .so файлов). Если же значительная нагрузка ложится на ядро или внешние сервисы (например комбинация из postgresql + python) то оно становится вообще единственным средством, помогающим понять «кто все съел».
Все серьезные современные процессоры имеют встроенную поддержку стат профилирования через аппара
тные счетчики событий производительности. Если кратко то в каждом ядре есть несколько регистров (для core 2 — 7), которые можно настроить на подсчет определенного типа событий, например тактов процессора, исполненных инструкций, промахов в кеши, TLB и т.п.
Обычно счетчики настраиваются на вызов прерывания при достижении определенного значения (например 1M тактов CPU), по входу в прерывание управление передается модулю профилировщика. В линукс до 2.6.31 поддержка аппаратных счетчиков была в основном в intel vtune и oprofile.
Большим плюсом счетчиков является возможность понять почему код работает с наблюдаемой скоростью, посколько они позволяют разложить время исполнения на более мелкие составляющие.
Начнем с динозавра стат профилирования — oprofile:
## установим отладочные символы для вывода имен функций
# apt-get install oprofile python2.7-dbg python2.7-dev postgresql-9.1-dbg
# apt-get install libc6-dbg zlib1g-dbg libssl1.0.0-dbg
# запускаем модуль
# opcontrol --init
# PYTHON=/usr/bin/python2.7
# POSTGRES=/usr/lib/postgresql/9.1/bin/postgres
## настраиваем профайлер - не следить за ядром, используем
## такты процессора в качестве события профилирования, мониторить только
## питон, постгрес и библиотеки в их адресном пространстве
# opcontrol --no-vmlinux --event=CPU_CLK_UNHALTED:1000000
-i "$PYTHON,$POSTGRES" --separate=lib
## инициализируем базу - код теста приведен в конце статьи и лежит на git
# python test_psql.py psql fill 100000
## запускаем тест - выполнятеся 10M простейших 'select val from test_table where key=some_val'
# opcontrol --start; python test_psql.py psql read 10000000; opcontrol --stop
# opcontrol --dump
# opcontrol --shutdown
# opcontrol --deinit
# opreport -l | less
По итогу получаем следующий вывод:
CPU: Intel Architectural Perfmon, speed 2001 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 1000000
samples % image name app name symbol name
119760 2.0987 postgres postgres AllocSetAlloc
103579 1.8152 libc-2.13.so postgres strcoll_l
100119 1.7545 postgres postgres SearchCatCache
96138 1.6848 libcrypto.so.1.0.0 postgres sha1_block_data_order
93466 1.6379 libcrypto.so.1.0.0 python2.7 sha1_block_data_order
92630 1.6233 postgres postgres base_yyparse
89759 1.5730 libc-2.13.so postgres __memcpy_ssse3_back
71632 1.2553 libc-2.13.so postgres _int_malloc
71214 1.2480 libc-2.13.so python2.7 _int_malloc
70112 1.2287 libz.so.1.2.3.4 python2.7 longest_match
66124 1.1588 libcrypto.so.1.0.0 python2.7 _x86_64_AES_decrypt_compact
64521 1.1307 libcrypto.so.1.0.0 postgres _x86_64_AES_decrypt_compact
64130 1.1238 libc-2.13.so python2.7 __memcpy_ssse3_back
56956 0.9981 libc-2.13.so python2.7 malloc
52380 0.9179 libcrypto.so.1.0.0 postgres _x86_64_AES_encrypt_compact
52216 0.9151 libcrypto.so.1.0.0 postgres EVP_MD_CTX_cleanup
49158 0.8615 libcrypto.so.1.0.0 python2.7 _x86_64_AES_encrypt_compact
47041 0.8244 libz.so.1.2.3.4 python2.7 build_tree
46747 0.8192 libcrypto.so.1.0.0 python2.7 EVP_MD_CTX_cleanup
45194 0.7920 libz.so.1.2.3.4 postgres build_tree
42862 0.7511 libc-2.13.so python2.7 free
Итого: основное время системы проводит освобождая/выделяя память, шифруя передаваемую информацию и разбирая sql запросы.
Несмотря на то, что oprofile достаточно удобен его возможностей не хватало и длительное время Stephane Eranian разрабатывал perfmon3 — поддержку счетчиков проиводительности в ядре linux, которая однако никак не попадала в основное ядро…. А потом неожиданно появился Thomas Gleixner и вездесущий Ingo Molnar, которые предложили perf патч для ядра и одновременно закидали конфетами perfmon. Чуть позже Торвальдс закидал теми же конфетами разработчиков oprofile и одобрил включение утилит пользовательского режима для поддержки perf подсистемы в состав ядра.
В итоге патч был включен в Linux 2.6.31 и сейчас perf, IMHO, самая удобная утилита для профилирования бинарного кода в linux. perf входит в состав пакета linux-tools-common (ubuntu). Те, кто использует последние версии ядра из …. (к которым нет linux-tools-common) могут скачать исходники соответвующего ядра с kernel.org, перейти в папку tools/perf, сделать там make и скопировать полученный perf в /usr/bin/perf_USED_LINUX_KERNEL_VERSION
$ cd tools/perf
$ make
$ sudo cp perf /usr/bin/perf_`uname -r`
По сравнению с oprofile модуль ядра perf получил:
более чистый API
- больше аппаратных счетчиков
(сравните «opcontrol —list-events» и «perf list | grep '[Hardware'»)
поддержку в структурах ядра (теперь при переключении процессов ядро сохраняет счетчики для старого процесса в его структуре и загружает в регистры процессора созраненные счетчики нового процесса — это улочшает результаты профилирования в многопоточной среде)
програмные счетчики — события из ядра: переключения контекстов, minor/major page fault, счетчики системных вызовов и интеграцию c systemtap.
Но конечных пользователей больше интересуют утилиты пользовательского режима, и тут много всего полезного ( perf невозможно использовать при загруженном модуле oprofile, так как они используют одни и те же апаратные регистры. Перед использованием perf необходимо выгрузить oprofile — «oprofile —deinit» ):
perf top — показывает в реальном времени какие функции/процессы в системе генерируют больше всего нагрузки. Например «perf top» покажеть распределение нагрузки по функциям. «perf top -e L1-dcache-loads» покажет кто хуже всех относится к кешу процессора «perf top -e dTLB-load-misses,iTLB-load-misses» покажет промахи в TLB и позволит оценить имеет ли смысл переключаться на огромные страници.
perf stat cmd генерирует отчет по отдельной команде — аналог утилиты time.
$ perf stat ps
PID TTY TIME CMD
19784 pts/2 00:00:00 sudo
19785 pts/2 00:00:00 perf
19786 pts/2 00:00:00 ps
Performance counter stats for 'ps':
13.633273 task-clock # 0.962 CPUs utilized
9 context-switches # 0.001 M/sec
1 CPU-migrations # 0.000 M/sec
284 page-faults # 0.021 M/sec
21,595,618 cycles # 1.584 GHz [70.79%]
10,181,093 stalled-cycles-frontend # 47.14% frontend cyc
les idle [70.90%]
6,232,603 stalled-cycles-backend # 28.86% backend cycles idle [80.06%]
31,611,007 instructions # 1.46 insns per cycle
# 0.32 stalled cycles per insn
6,798,332 branches # 498.657 M/sec
60,662 branch-misses # 0.89% of all branches [79.08%]
0.014176162 seconds time elapsed
perf record cmd исполняет программу и сохраняет итог профилирования в perf.dat, «perf report» позволит его просмотреть, а «perf annotate» покажет распределение событий по строкам исходного текста или по ассемблерному листингу.
Также perf «знает» о потоках, позволяя просматривать события для каждого потока в отдельности и умеет использовать встроенные в процессор средства тонкой настройки работы счетчиков.
В отличии от oprofile я не нашел как заставить perf записывать события только для некоторого набора бинарных файлов, но есть возможность поместить все необходимые процессы в отдельную группу(cgroup) и мониторить только ее.
Возможности perf на этом не исчерпываются, «perf help» покажет много полезных инструментов.
Пример использования perf с тем же тестом, что и oprofile:
$ perf record -e cycles -c 1000000 python test_psql.py psql read 10000000
## просыпаемся раз в 1М тактов (~2к раз в секунду)
............
$ perf report
1.59% postgres postgres [.] AllocSetAlloc
1.46% postgres libc-2.13.so [.] __strcoll_l
1.35% postgres postgres [.] SearchCatCache
1.25% postgres libcrypto.so.1.0.0 [.] sha1_block_data_order
1.24% python libcrypto.so.1.0.0 [.] sha1_block_data_order
1.19% postgres libc-2.13.so [.] __memcpy_ssse3_back
1.13% postgres postgres [.] base_yyparse
0.94% python libz.so.1.2.3.4 [.] longest_match
0.94% postgres libc-2.13.so [.] _int_malloc
0.91% python libc-2.13.so [.] _int_malloc
0.87% python libcrypto.so.1.0.0 [.] _x86_64_AES_decrypt_compact
0.85% postgres libcrypto.so.1.0.0 [.] _x86_64_AES_decrypt_compact
0.82% python libc-2.13.so [.] __memcpy_ssse3_back
0.78% python libc-2.13.so [.] malloc
0.69% postgres libcrypto.so.1.0.0 [.] _x86_64_AES_encrypt_compact
0.67% postgres libcrypto.so.1.0.0 [.] EVP_MD_CTX_cleanup
0.67% python libcrypto.so.1.0.0 [.] _x86_64_AES_encrypt_compact
0.66% python libz.so.1.2.3.4 [.] build_tree
0.63% python libcrypto.so.1.0.0 [.] EVP_MD_CTX_cleanup
0.60% postgres libz.so.1.2.3.4 [.] build_tree
0.59% python libc-2.13.so [.] free
0.54% postgres postgres [.] hash_search_with_hash_value
0.53% postgres libz.so.1.2.3.4 [.] _tr_flush_block
0.52% python libz.so.1.2.3.4 [.] _tr_flush_block
0.50% python python2.7 [.] convertitem
.......
О накладных расходах: perf замедлял тест примерно на ~0.5%, а oprofile на 2-5%. Увеличивая порог срабатывания события можно уменьшить влияние профилировшика, но прийдется соответвенно удлиннить тесты для сохранения качества результатов.
В итоге perf дейсвительно Замечательный Инструмент, который позволяет не только профилировать свои программы но и практически незаметно мониторить что происходит в живой системе.
Исходники утилиты для тестов(требуют библиотеку futures):
import sys
import time
import Queue
import futures
import psycopg2
import traceback
import multiprocessing
def exec_opers(test_class, start, stop, res_q, ops):
"""
Split test on chunks and put chunk size to result queue
when chunk execution finished
"""
try:
test_obj = test_class()
stops = range(start, stop, ops)[1:] + [stop]
curr_start = start
for curr_stop in stops:
test_obj.run(curr_start, curr_stop)
res_q.put(curr_stop - curr_start)
except Exception, x:
traceback.print_exc()
raise
finally:
# None mean thread finish work
res_q.put(None)
def do_tests(test_class, size, ops, th_count=None):
"run some amount of tests in separated threads"
if th_count is None:
th_count = multiprocessing.cpu_count()
res_q = Queue.Queue()
num_per_thread = size // th_count
with futures.ThreadPoolExecutor(max_workers=th_count) as executor:
vals = [(i * num_per_thread,
(i + 1) * num_per_thread)
for i in range(th_count)]
for start, stop in vals:
executor.submit(exec_opers, test_class, start, stop, res_q, ops)
left = th_count
done = 0
ppers = 0
pval = 0
ptime = time.time()
PERC_PER_STEP = 10
while left != 0:
try:
val = res_q.get(timeout=0.1)
if val is None:
left -= 1
else:
done += val
np = int(done * (100 / PERC_PER_STEP) / size)
if np != ppers:
ntime = time.time()
if ntime - ptime < 1E-3:
speed = "Too fast"
else:
speed = int((done - pval) / (ntime - ptime))
print "{0}% done. Performanc
e - {1} ops/sec".format(
int(done * 100 / size), speed)
ptime = ntime
pval = done
ppers = np
except Queue.Empty:
pass
class PSQLBase(object):
def __init__(self):
self.conn, self.curr = self.conn_and_cursor()
self.curr.execute("select count(*) from test_table")
self.db_sz = int(self.curr.fetchone()[0])
def __del__(self):
self.curr.close()
self.conn.close()
@classmethod
def conn_and_cursor(cls):
conn = psycopg2.connect("host=localhost dbname=test user=test password=test")
return conn, conn.cursor()
@classmethod
def clear_data(cls):
conn, curr = cls.conn_and_cursor()
curr.execute("delete from test_table")
conn.commit()
curr.close()
conn.close()
@classmethod
def insert_data(cls, sz, step=1000):
conn, curr = cls.conn_and_cursor()
for i in range(sz / step):
vals = [(str(i * step + j), 'test_data') for j in range(step)]
curr.executemany("insert into test_table (key, val) values (%s, %s)", vals)
conn.commit()
curr.close()
conn.close()
class PSQLRead(PSQLBase):
def run(self, start, stop):
for i in xrange(start, stop):
self.curr.execute("select val from test_table where key=%s", (str(i % self.db_sz),))
self.curr.fetchall()
class PSQLWrite(PSQLBase):
def run(self, start, stop):
for i in xrange(start, stop):
self.curr.execute("insert into test_table (key, val) values (%s, %s)", (str(i), 'test data'))
self.conn.commit()
def main(argv=None):
if argv is None:
argv = sys.argv[1:]
tp = argv[0]
if tp == 'psql':
Base, R, W = PSQLBase, PSQLRead, PSQLWrite
argv = argv[1:]
if argv[0] != 'clear':
sz = int(argv[1])
if argv[0] == 'clear':
Base.clear_data()
elif argv[0] == 'fill':
Base.insert_data(sz)
elif argv[0] == 'read':
do_tests(R, sz, 1000)
elif argv[0] == 'write':
do_tests(W, sz, 50)
else:
print "Unknown cmd '%s'" % argv[0]
return 1
return 0
if __name__ == "__main__":
sys.exit(main(sys.argv[1:]))
И скрипта для профилирования:
#!/bin/bash
set -x
PROFILER=perf
PYTHON=/usr/bin/python2.7
POSTGRES=/usr/lib/postgresql/9.1/bin/postgres
OK=0
if [ "$PROFILER" == "oprofile" ] ; then
OK=1
opcontrol --init
opcontrol --reset
opcontrol --callgraph=10 --no-vmlinux --event=CPU_CLK_UNHALTED:1000000 -i "$PYTHON,$POSTGRES" --separate=lib
opcontrol --start
fi
if [ "$PROFILER" == "perf" ] ; then
OK=1
rm perf.data perf.data.old 2>&1 >/dev/null
fi
if [ "0" == "$OK" ] ; then
echo "Unknown profiler $PROFILER" >&2
exit 1
fi
if [ "$PROFILER" == "oprofile" ] ; then
$PYTHON test_psql.py $@
else
perf record -a -g $PYTHON test_psql.py $@
fi
if [ "$PROFILER" == "oprofile" ] ; then
opcontrol --dump
opcontrol --shutdown
opcontrol --deinit
fi
P.S. Приведенная утилита ни в коем случае не предназначается в текущем варианте для тестов PostgreSQL или чего либо еще. Ее единственная задача — показать работу профилировщика.
Исходники этого и других постов со скриптами лежат тут — my blog at githubПри использовании их, пожалуйста, ссылайтесь на koder-ua.blogspot.com
Автор: konstantin danilov
