Профилирование со сверхсветовой скоростью: теория и практика. Часть 1

Привет! Из заголовка вы уже поняли, о чём я собираюсь рассказать. Тут будет много хардкора:
мы обсудим Java, С, С++, ассемблер, немного Linux, немного ядра операционной системы. А ещё разберём практический кейс, поэтому статья будет в трёх больших частях (достаточно объёмных).

В первой мы попробуем выжать всё возможное из существующих профилировщиков.
Во второй части сделаем собственный маленький профилировщик, а в третьей посмотрим, как же профилировать то, что профилировать не принято, потому что существующие инструменты не очень для этого подходят. Если готовы пройти этот путь — жду вас под катом :)

Содержание

• Время и средство постижения — профилировщик
• Как работают сэмплирующие профилировщики
• С какой частотой нам нужно сэмплировать
• Выбираем профилировщик
• Учим perf собирать профиль Java-приложения
• Увеличиваем частоту сэмплирования perf'а
• Используем (явно) аппаратные события PMU/PEBS
• Короткое резюме

Время и средство постижения — профилировщик

С житейской точки зрения, 1 секунда — это очень мало. Но мы-то знаем, что 1 секунда — это целый миллиард наносекунд. И пускай за 1 наносекунду всего лишь исполняется около 4 тактов процессора, за 1 секунду в компьютере выполняется очень много всего, что может улучшить или ухудшить нам жизнь.

Допустим, мы разрабатываем приложение, которое само по себе достаточно критично к быстродействию, а для некоторых фрагментов кода это вообще критично. Эти кусочки исполняются, скажем, сотни микросекунд — достаточно быстро, но они [участки кода] напрямую влияют на успешность нашего приложения и на количество зарабатываемых или теряемых денег. Например,
при отправке ордеров на заключение биржевых сделок задержка в 100 мкс может стоить бирже 1 млн. рублей и более на каждой сделке, которых в день проходит не одна, и не две, и даже не сто.

И мне была поставлена задача: с одной стороны, нужно отправить все ордеры одновременно, а с другой стороны — отправить их так, чтобы дисперсия между первым и последним была минимальна. То есть необходимо было отпрофилировать функцию, которая отправляет ордеры на биржу. Типичная задача, кроме одного маленького нюанса: характерное время исполнения этой функции существенно меньше 100 мкс.

Давайте подумаем, как нам профилировать эти 100 мкс, чтобы понять, что происходит внутри.
Что необходимо учитывать, выбирая этот инструмент?

1. Интересующий нас участок кода исполняется достаточно редко, то есть 100 мкс исполняются где-то раз в секунду. И это в тестовом стенде, а в production и того реже.
2. Этот кусочек кода достаточно сложно будет выделить в микробенчмарк, потому что он затрагивает заметную часть проекта, да еще и ввод/вывод через сеть.
3. И наконец, самое важное, хочется, чтобы полученный профиль соответствовал тому поведению, которое будет на наших production-серверах.

Как же нам учесть все эти нюансы и правильно отпрофилировать интересующий метод?

Концептуально, все профилировщики можно разделить на две группы профилировщиков инструментирующие или сэмплирующие. Рассмотрим каждую группу в отдельности.

Инструментирующие профилировщики вносят достаточно большие накладные расходы, потому что они модифицируют наш байт-код и вставляют в него запись таймингов. Отсюда ключевой недостаток таких профилировщиков: они могут существенно влиять на исполняемый код. В результате будет трудно сказать, насколько полученный профиль соответствует поведению на production-серверах: какие-то оптимизации могут работать иначе, какие-то случаются, а какие-то нет. Возможно, в других масштабах времени, — секунды, минуты, часы, — мы получим репрезентативные данные. Но в масштабе 100 мкс сработавшая или не сработавшая оптимизация может привести к тому, что профиль окажется совершенно не репрезентативен. Поэтому давайте присмотримся к другой группе профилировщиков.

Сэмплирующие профилировщики вносят либо минимальные, либо умеренные накладные расходы. Эти инструменты не влияют напрямую на исполняемый код, а их использование требует от вас чуть больше внимания. Поэтому остановимся именно на сэмпиирующих профилировщиках. Давайте посмотрим, какие данные и в каком виде мы будем получать от них.

Как работают сэмплирующие профилировщики?

Для того, чтобы понять, как работает сэмплирующий профилировщик, рассмотрим следующий пример — метод sendToMoex вызывает несколько других методов. Смотрим:

void sendToMoex() {
  a.qqq();
  b.doo();
  c.ccc()
}

void doo() {
  d.a();
  d.b();
}

Если мы будем наблюдать за состоянием стека вызовов в момент выполнения этого участка программы и периодически его записывать, то получим информацию в примерно таком виде:

Это набор стеков вызовов. Если предположить, что сэмплы распределены достаточно равномерно, то количество одинаковых стеков свидетельствует об относительном времени выполнения того метода, который находится на вершине стека.

В данном примере, метод D.a выполнялся столько же, сколько метод C.ccc, и это в 2 раза больше, чем метод D.b. Однако предположение о равномерности распределения сэмплов может оказаться не совсем верным, и тогда оценка времени выполнения будет некорректной.

С какой частотой нам нужно сэмплировать?

Допустим, мы хотим за 100 мкс взять 1000 сэмплов, чтобы понять, что там внутри исполнялось. Далее простой пропорцией вычисляем, что если нам нужно делать 1000 сэмплов в 100мкс, то это 10 млн. сэмплов за 1 секунду или 10.000.000 сэмплов/с.

Если мы будем сэмплировать на такой скорости, то за одно исполнение кода мы соберём 1000 сэмплов, агрегируем и поймём, что работало быстро или медленно. После этого будем анализировать производительность и корректировать код.

Однако частота 10 млн. сэмплов в секунду — это много. А если нам не удастся добиться такой скорости профилирования с самого начала? Допустим, мы собрали за 100 мкс всего лишь 10 сэмплов, а не 1000. В таком случае нам остается подождать следующего исполнения профилируемого кода, которое произойдет через 1 секунду (ведь профилируемый код выполняется раз в секунду). Так мы наберем ещё 10 сэмплов. Поскольку они у нас равномерно распределены, их можно объединять в общий набор. Достаточно подождать, пока профилируемый код исполнится 1000/10 = 100 раз, и мы наберём необходимые 1000 сэмплов (по 10 сэмплов каждый из 100 раз).

Выбираем профилировщик

Вооружившись этими теоретическими знаниями, давайте перейдём к практике.

Возьмём Async-profiler. Отличный инструмент (использует вызов виртуальной машины AsyncGetCallTrace), который собирает стек вызовов с точностью до инструкции байт кода виртуальной машины Java. Штатная частота сэмплирования async-profiler’а — 1000 сэмплов в секунду.

Решим простую пропорцию: 10.000.000сэмплов/сек — 1 секунда, 1000сэмплов/с — Х секунд.
Мы получим, что на штатной частоте сэмплирования async-profiler’а профилирование займет около 3 часов. Это долго. В идеале хочется собирать профиль максимально быстро, прямо-таки со сверхсветовой скоростью.

Попробуем разогнать Async-profiler. Для этого в readme находим флаг -i, который задаёт интервал сбора сэмплов. Попробуем установить флаг -i1 (1 наносекунда), или вообще -i0, чтобы профилировщик сэмплировал без остановки. У меня получилась частота около 2,5 тыс. сэмплов в секунду. В этом случае суммарная длительность профилирования составит порядка 1 часа. Конечно, не 3 часа, но и не особо быстро. Кажется, чтобы достичь требуемых скоростей профилирования нужно сделать что-то качественно другое, выйти на новый уровень.

Чтобы достичь существенно больших частот, придётся отказаться от вызова AsyncGetCallTrace и воспользоваться perf — штатным профилировщиком Linux, который есть в каждом дистрибутиве Linux’а. Однако perf ничего не знает про Java, и нам еще предстоит обучить perf работать с Java. А пока попробуем запустить perf вот таким страшным образом:

$ perf record –F 10000 -p PID -g -- sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: .. 0.215 MB perf.data (4032 samples) ]

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

Учим perf собирать профиль Java-приложения

Выполним команду perf record …, подождем 1 секунду и запустим perf script, чтобы посмотреть, что же напрофилировалось? И увидим что-то не очень понятное:

$ perf script

java 8079 2008793.746571:    3745505 cycles:uppp: 
            7fa1e88b53f8 [unknown] (/tmp/perf-11038.map)
java 8079 2008793.747565:    3728336 cycles:uppp: 
            7fa1e88b5372 [unknown] (/tmp/perf-11038.map)
java 8079 2008793.748613:    3731147 cycles:uppp: 
            7fa1e88b53ef [unknown] (/tmp/perf-11038.map)

Вроде бы это адреса, но нет имён Java-методов. Значит, нужно научить perf сопоставлять эти адреса с названиями методов.

В мире С и С++ для сопоставления адресов и имен функций используется так называемая отладочная информация. В специальной секции исполняемого файла хранится соответствие: по таким-то адресам лежит один метод, по другим адресам — другой метод. Perf эту информацию подтягивает и делает сопоставление.

Очевидно, что JIT-компилятор виртуальной машины не генерирует отладочную информацию в таком формате. Нам остается другой способ — записать данные о соответствии адресов и имен методов в специальный perf-map файл, который perf будет трактовать как дополнение к прочитанной отладочной информации. Этот perf-map файл должен лежать в папке tmp и иметь такую структуру данных:

Первая колонка — это адрес начала кода метода, вторая — его длина, третья колонка — имя метода.

Итак, нам нужно сгенерировать подобный файл. Очевидно, что сделать это вручную не получится (откуда мы знаем, по каким адреcам JIT-компилятор разместит код), поэтому воспользуемся скриптом create-java-perf-map.sh из проекта perf-map-agent, передав ему PID нашего Java-процесса. Файл готов, проверяем его содержимое, ещё раз запускаем perf-script.

$ perf script

java  8080 1895245.867498:    cycles:uppp: 
	7fb2dd10f527 Loop3.doRecursiveCall (/tmp/perf-8079.map)

java  8080 1895245.868176:    2127960 cycles:uppp: 
	7fb2dd10f57f Loop3.doRecursiveCall (/tmp/perf-8079.map)

java  8080 1895245.868737:    1959990 cycles:uppp: 
	7fb2dd10f627 Loop3.doRecursiveCall (/tmp/perf-8079.map)

Вуаля! Мы видим имена java-методов! Что же только что произошло: мы научили профилировщик perf, который ничего не знает про Java, профилировать обычное Java-приложение и видеть горячие java-методы этого приложения!

Однако для анализа производительности интерсующего нас куска программы нам не хватает call-stack’а, чтобы отфильтровать интересующие данные от всех собранных сэмплов.

Как получить стек вызовов?

Теперь нужно ещё что-то сделать с perf или виртуальной машиной, чтобы получить стеки вызовов. Чтобы понять, что же нужно сделать, давайте сделаем шаг назад и посмотрим, как вообще работает стек. Представим, что у нас есть три функции f1, f2, f3. Причем f1 вызывает f2, а f2 вызывает f3.

void f1() {
    f2();
}
void f2() {
    f3();
}
void f3() {
    ...
}

В момент исполнения функции f3 посмотрим, в каком состоянии находится стек. Мы видим регистр rsp, который указывает на вершину стека. Также мы знаем, что в стеке есть адрес предыдущего стекового кадра. А как можно получить call-stack?

Если бы мы могли как-то получить адрес этой области, то мы бы могли представить стек как односвязный список и понять ту последовательность вызовов, которая нас привела в текущую точку исполнения.

Что же нам для этого нужно? Нам нужен дополнительный регистр rbp, который будет указывать на желтую область. Получается, что регистр rbp позволяет perf получить стек вызовов, понять последовательность, которая нас привела в текущую точку. Подробнее эти детали рекомендую прочитать в System V Application Binary Interface. Там описано, как происходит вызов методов в Linux.

Мы поняли, в чем наша проблема. Нам нужно заставить виртуальную машину использовать регистр rbp по его изначальному назначению — в качестве указателя на начало стекового кадра. Именно так JIT-компилятор должен использовать регистр rbp. Для этого в вирутальной машине есть флажок PreserveFramePointer. Когда мы передадим виртуальной машине этот флаг, то виртуальная машина начнет использовать регистр rbp по его традиционному назначению. И тогда Perf сможет раскрутить стек. И мы получим в профиле настоящий колл-стек. Флажок был законтрибьючен небезызвестным Бренданом Греггом всего лишь в JDK8u60.

Запускаем виртуальную машину с новым флагом. Выполняем create-java-perf-map, затем perf record и perf script. Теперь мы умеем собирать точный профиль со стеками вызовов:

$ perf script

java 18657 1901247.601878:     979583 cycles:uppp: 
            7fbfd1101edc Loop3.doRecursiveCall (...)
            7fbfd1101edc Loop3.doRecursiveCall (...)
            7fbfd1101edc Loop3.doRecursiveCall (...)
            7fbfd1101edc Loop3.doRecursiveCall (...)
            7f285d007b10 Interpreter (...)
            7f285d0004e7 call_stub (...)
                  67d0db [unknown] (... libjvm.so)
...
                    708c start_thread (... libpthread-2.26.so)

Мы научили профилировщик perf, входящий в комплект большинства дистрибутивов Linux, работать с Java-приложениями. Поэтому теперь мы можем видеть не только горячие участки кода, но и ту последовательность вызовов, которая привела к текущему горячему месту. Отличное достижение, если учесть, что профилировщик perf ничего не знает про java. Всему этому мы только что научили perf!

Увеличиваем частоту сэмплирования perf'а

Попробуем разогнать perf до 10 млн сэмплов в секунду. Сейчас у нас частота существенно меньше.

Чтобы автоматизировать все задачи, которые мы только что делали, можно воспользоваться скриптом perf-java-record-stack из проекта perf-map-agent. У него есть замечательная ручка — переменная окружения perf_record-freq, с помощью которой можно задать частоту сэмплирования. Сначала зададим 100 тыс. сэмплов в секунду и попробуем запустить. В консоли появляется грозное сообщение, что мы превысили максимально дозволенную частоту сэмплирования:

$ PERF_RECORD_FREQ=100000 ./bin/perf-java-record-stack PID
...
Maximum frequency rate (30000) reached.
Please use -F freq option with lower value or consider
tweaking /proc/sys/kernel/perf_event_max_sample_rate.
...

В моем случае лимит был в 30 тыс. сэмплов в секунду. Perf сразу говорит, какой аргумент ядра нужно поправить, что мы и сделаем либо с помощью echo sudo tee в нужный файл, либо напрямую через sysctl. Так:

$ echo '1000000' | 
sudo tee /proc/sys/kernel/perf_event_max_sample_rate 

или так:

$ sudo sysctl kernel.perf_event_max_sample_rate=1000000

Сейчас мы говорим ядру, что верхний предел частоты теперь 1 млн. сэмплов в секунду. Запускаем профилировщик ещё раз и указываем частоту 200 тыс. сэмплов в секунду. Профилировщик проработает 15 секунд и выдаст нам 1 млн. сэмплов. Вроде бы всё хорошо. По крайней мере никаких грозных сообщений об ошибках. Но какую же частоту мы получили на самом деле? Оказывается, всего лишь 70 тыс. сэмплов в секунду. Что же пошло не так?

Давайте посмотрим вывод команды dmesg:

[84430.412898] perf: interrupt took too long (1783 > 200), lowering kernel.perf_event_max_sample_rate to 89700
...
[84431.618452] perf: interrupt took too long (2229 > 2228), lowering kernel.perf_event_max_sample_rate to 71700

Это вывод ядра ОС Linux. Оно поняло, что мы сэмплируем слишком часто, и это занимает слишком много времени, поэтому ядро понижает частоту. Получается, нам нужно выкрутить ещё одну ручку в ядре — она называется kernel.perf_cpu_time_max_percent и регулирует количество времени, которое ядро может тратить на прерывания от perf.

Закажем частоту сэмплирования 200 тыс. сэмплов в секунду. И через 15 секунд мы получаем 3 млн. сэмплов — 200 тыс. сэмплов в секунду.

$ PERF_RECORD_FREQ=200000 ./bin/perf-java-record-stack PID
Recording events for 15 seconds ...
...
[ perf record: Captured ... (2.961.252 samples) ]

Теперь посмотрим профиль. Запускаем perf script:

$ perf script
...
java ... native_write_msr (/.../vmlinux)
java ... Loop2.main (/tmp/perf-29621.map)
java ... native_write_msr (/.../vmlinux)
...

Видим странные функции и исполняемый модуль vmlinux — ядро Linux. Это точно не наш код. Что же произошло? Частота оказалась настолько большой, что в сэмплы начал попадать код ядра. То есть чем выше мы будем поднимать частоту, тем больше будет сэмплов, которые относятся не к нашему коду, а к ядру Linux.

Тупик.

Используем (явно) аппаратные события PMU/PEBS

Тогда я решил попробовать воспользоваться аппаратной технологией PMU/PEBS — Performance Monitoring Unit, Precise Event Based Sampling. Она позволяет получать уведомления о том, что какое-то событие произошло заданное количество раз. Это называется «период». Например, мы можем получать уведомления об исполнении процессором каждой 20-й инструкции. Давайте посмотрим это на примере. Пусть сейчас исполняется инструкция xor, а PMU-счётчик получает значение 18; затем идёт инструкция mov — счётчик равен 19; и следующую инструкцию, add %r14, %r13, PMU будет показывать как «горячую».

Дальше начинается новый цикл: исполняется inc — PMU сбрасывается до 1. Проходит ещё несколько итераций цикла. В итоге мы останавливаемся на инструкции mov, PMU отщелкивает 19. Следующая инструкция add, и опять мы помечаем её как «горячую». Смотрим листинг:

mov aaa, bbbb
xor    %rdx, %rdx
L_START:
mov    $0x0(%rbx, %rdx),%r14
add    %r14, %r13  ;  (PMU будет показывать только эту инструкцию как "горячую")
cmp    %rdx,100000000
jne    L_START

Не замечаете странностей? Цикл из пяти инструкций, но каждый раз мы помечаем одну и ту же инструкцию как горячую. Очевидно, что это неправда: все инструкции «горячие». На них тоже тратится время, а мы помечаем только одну. Дело в том, что у нас между периодом и счетчиком количества инструкций в итерации есть общий делитель 4. Получается, каждую четвёртую итерацию мы будем помечать одну и ту же инструкцию как «горячую». Чтобы избежать такого поведения, нужно в качестве периода выбирать такое число, при котором минимизируется вероятность появления общего делителя между количеством итераций в цикле и самим счётчиком. В идеале период должен быть простым числом, т.е. делиться только на себя и на единицу. Для примера выше: следовало бы выбрать период равный 23. Тогда бы мы поровну помечали все инструкции в этом цикле как «горячие».

Технология PMU/PEBS поддерживается в современном виде как минимум с 2009 года, то есть она есть почти на любых компьютерах. Чтобы применить ее явно, давайте модифицируем скрипт perf-java-record-stack. Заменим флаг -F на -e, который явным образом задаёт использование PMU/PEBS.

...
sudo perf record -F $PERF_RECORD_FREQ ...
...

Перевоплощаем скрипт:

...
sudo perf record -e cycles –c 10007 ...
...

Вы уже знаете, какими свойствами должен обладать период — нам нужно простое число. Для нашего случая это будет период 10007.

Запустили модифицированный скрипт perf-java-record-stack и за 15 секунд получили 4,5 млн. сэмплов — это почти 300 тыс. в секунду, по одному сэмплу каждые 3 мкс. То есть за одно исполнение нашего профилированного кода, за 100 мкс мы будем набирать 33 сэмпла. При такой частоте общая длительность сбора профиля составит всего лишь 30 секунд. Даже чашку кофе не выпить! В реальности же всё немного сложнее. Что будет, если наш код станет исполняться не раз в секунду, а раз в 5 секунд? Тогда длительность профилирования вырастет до 2,5 минут, что тоже вполне достойный результат.

Итак, за 30 секунд можно получить профиль, который полностью покроет все наши потребности в исследовании. Победа?

Но меня не покидало ощущение какого-то подвоха. Вернемся к ситуации, при которой наш код исполняется раз в 5 секунд. Тогда профилирование займёт 150 секунд, за это время мы соберем около 45 млн. сэмплов. Из них нам нужны лишь 1000, то есть 0,002 % собранных данных. Всё остальное — мусор, который замедляет работу других инструментов и добавляет накладные расходы. Да, задача решена, но решена в лоб, грязно, тупой силой.

И в тот вечер, когда я впервые получил с помощью perf’а такой подробный профиль, у меня появилась мечта. Я шел с работы домой и думал, а вот бы было хорошо, если железо умело само собирать профиль да еще и с точностью до инфтрукций и микросекунд, а мы бы только анализировали результаты. Сбудется ли моя мечта? Как вы думаете?

Короткое резюме:

• Чтобы собрать профиль Java-приложения с помощью perf’а необходимо сгенерировать файл с информацией о символах с помощью скриптов из проекта perf-map-agent
• Чтобы собирать информацию не только про горячие участки кода, но и стеки, нужно запускать виртуальную машину с флагом -XX:+PreserveFramePointer
• Если хочется увеличить частоту сэмплирования, стоит обратить внимание на sysctl’и kernel.perf_cpu_time_max_percent и kernel.perf_event_max_sample_rate.
• Если в профиль начали попадать сэмплы из ядра, не относящиеся к приложению, стоит задуматься о явном указании периода PMU/PEBS.

Эта статья (и последующие её части) является расшифровкой доклада, адаптированного в текстовом виде. Если хочется не только прочитать, но и послушать про профилирование, ссылочка на выступление.

Автор: Sergey Melnikov

Источник