March 20, 2012

perf : современный Linux профилировщик

Иногда возникает необходимость заглянуть внутрь программы, что-бы посмотреть почему она "так тормозит". Естественно начинается все с высокоуровневых средств 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

2 comments:

Anonymous said...

Очень интересная и полезная статья, буду не раз к ней возвращаться и размышлять.
есть неплохой профилировщик от Intel, кстати. Не пробовали?

Сергей Ивачев said...

У меня есть небольшая проблема (Python). Может подскажете? Как с Вами связаться? Мой e-mail: sepatan@sibmail.com