Иногда возникает необходимость заглянуть внутрь программы, что-бы посмотреть почему она "так тормозит". Естественно начинается все с высокоуровневых средств 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 cycles 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. Performance - {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
4 comments:
Очень интересная и полезная статья, буду не раз к ней возвращаться и размышлять.
есть неплохой профилировщик от Intel, кстати. Не пробовали?
У меня есть небольшая проблема (Python). Может подскажете? Как с Вами связаться? Мой e-mail: sepatan@sibmail.com
Thanks for this article.You can visit my website:download magic jack for android
I Love your article. You can visit my website : subway surfer app free download for android
Post a Comment