Профилирование CPU: сэмплирование, flame graphs, горячие пути

Инженер, который «знает, где тормозит», почти всегда ошибается. Это не оскорбление, а воспроизводимый факт: интуиция натренирована на сложности алгоритма и объёме кода, а время съедают вещи без визуального веса — компиляция регулярки внутри цикла, аллокация на 24 байта миллион раз в секунду, промах кэша на невинном разыменовании. Профайлер существует ровно для того, чтобы заменить «я думаю» на «я измерил». Метрики и перцентили мы разобрали в https://courses.digitable.life/post/performance/01-measuring/, честный замер — в https://courses.digitable.life/post/performance/02-benchmarking/. Теперь берём микроскоп: как сэмплирующий профайлер устроен внутри, почему он врёт (а он врёт, и предсказуемо), как читать flame graph и когда полученная картинка вообще не про вашу проблему.

Ключевая мысль: профиль — это не запись выполнения программы, а статистическая оценка распределения времени по стекам вызовов. Всё остальное — следствия этого предложения.

1. Профиль против метрики: разные вопросы

Метрика (RED/USE) отвечает на вопрос «сколько и как плохо»: p99 равен 800 мс, утилизация CPU — 86%. Профиль отвечает на вопрос «на что именно потрачены эти 86%». Разные приборы, и подменять один другим — типичная ошибка.

Отсюда правило маршрутизации: если проблема в хвосте (p99 плохой, p50 отличный), профиль общего вида покажет самый частый путь, то есть как раз то, что работает нормально. Хвосты ловят трассировкой и профилями, отфильтрованными по медленным запросам. Если деградировала вся кривая — профиль именно тот инструмент.

2. Две школы: инструментирование против сэмплирования

Инструментирующий (детерминированный) профайлер вставляет учёт на входе и выходе каждой функции: cProfile в Python, gprof в C, трассировка методов в dotnet-trace. Он знает точное число вызовов и точное время каждого. Цена — накладные расходы 30–500%, и, что хуже, они неравномерны: дорожает то, что вызывается часто, поэтому доля мелких функций систематически преувеличивается. Вдобавок инструментирование ломает инлайнинг — компилятор не встраивает функцию, вокруг которой стоят пробы, и вы измеряете код, которого в проде не существует.

Сэмплирующий (статистический) профайлер периодически прерывает программу и записывает, где она была: perf, pprof, py-spy, async-profiler, профайлер Chrome DevTools. Накладные расходы постоянны и настраиваются частотой, включать можно на живом проде, измеряется реальный оптимизированный код. Минус — не знает количества вызовов, теряет редкое и страдает от смещений, о которых ниже.

Правило: начинайте с сэмплирования всегда. К инструментированию переходите, когда сэмплирование указало на подозреваемого и нужно точное число вызовов: «функция занимает 12% — она медленная или её зовут 4 миллиона раз?»

3. Сэмплирование — это статистика, а не наблюдение

Профайлер на 99 Гц за 30 секунд соберёт около 2970 сэмплов на поток. Каждый сэмпл — испытание Бернулли: «был ли в этот момент кадр F в стеке». Доля сэмплов с F — оценка доли времени, а у оценки есть доверительный интервал.

Стандартная ошибка доли p при n сэмплах равна √(p(1−p)/n); для маленьких долей относительная погрешность примерно 1/√k, где k — число сэмплов, попавших в кадр. Рабочие ориентиры: 100 сэмплов в кадре дают около ±10% от собственного значения, 25 сэмплов — ±20%, 4 сэмпла — ±50%, то есть чистый шум. Проверим руками:

"""Сколько сэмплов нужно, чтобы верить строчке в профиле."""
import random, statistics

def spread(true_share: float, n: int, runs: int = 2000) -> tuple[float, float]:
    """runs раз имитируем профилировку из n сэмплов и смотрим разброс наблюдаемой доли."""
    obs = [sum(random.random() < true_share for _ in range(n)) / n for _ in range(runs)]
    q = statistics.quantiles(obs, n=100)
    return q[1], q[97]          # примерно p2..p98; сложность O(runs * n) времени, O(runs) памяти

for share in (0.30, 0.05, 0.01):
    for n in (300, 3000, 30000):
        lo, hi = spread(share, n)
        print(f"доля {share:5.0%}, {n:6d} сэмплов -> наблюдаем {lo:6.2%}..{hi:6.2%}")

доля   30%,    300 сэмплов -> наблюдаем 24.67%..35.67%
доля   30%,   3000 сэмплов -> наблюдаем 28.30%..31.83%
доля    5%,    300 сэмплов -> наблюдаем  2.67%.. 8.00%
доля    5%,   3000 сэмплов -> наблюдаем  4.23%.. 5.87%
доля    1%,    300 сэмплов -> наблюдаем  0.00%.. 2.67%

Читайте последнюю строку внимательно: функция, честно съедающая 1% CPU, при тридцатисекундном профиле может вообще не появиться в отчёте — или показаться на 2,7%. Отсюда три следствия, экономящих дни работы.

1. Профилируйте дольше, а не чаще. Удвоение времени и удвоение частоты одинаково влияют на статистику, но частота линейно поднимает накладные расходы и сильнее искажает поведение программы.
2. Не сравнивайте два профиля на глаз. Разница в 3 процентных пункта между «до» и «после» — обычно шум. Для сравнения есть pprof -diff_base и дифференциальные flame graphs, но и им нужно достаточное n.
3. Редкое дорогое событие профиль не покажет. GC-пауза раз в минуту на 300 мс даёт 0,5% CPU и утонет в отчёте — при том что именно она формирует ваш p99.

Практический вывод: прежде чем оптимизировать строчку профиля, посмотрите на абсолютное число сэмплов, а не на проценты. В perf report его показывает --show-nr-samples, в pprof столбец flat уже выражен во времени, то есть в сэмплах, умноженных на период.

4. Что происходит между тиком и строчкой в отчёте

Разберём Linux perf как эталон — остальные профайлеры повторяют ту же схему на своём уровне.

Источник тиков бывает двух видов. Софтверный (cpu-clock, task-clock) — таймер высокого разрешения: просто, работает в виртуалках и контейнерах, где PMU недоступен. Аппаратный (cycles, instructions, cache-misses) — блок мониторинга производительности процессора: счётчик программируется на переполнение через N событий и вызывает немаскируемое прерывание. Разница принципиальна: cpu-clock меряет время, cycles меряет такты. Если процессор скинул частоту или ушёл в C-состояние, картины разойдутся — и разойдутся в интересных местах.

Две детали, о которых стоит знать заранее.

Skid. Между переполнением счётчика и доставкой прерывания процессор успевает выполнить ещё десятки инструкций, поэтому адрес в сэмпле «уезжает» вперёд: perf annotate может приписать 40% времени инструкции, стоящей сразу за настоящей виновницей. Лечится аппаратно — PEBS у Intel и IBS у AMD записывают точное состояние; в perf это суффиксы точности cycles:pp и cycles:ppp. Профиль уровня инструкций без :pp — заведомо смещённая картина.

Частота 99 Гц, а не 100. Классический приём Брендана Грегга: если программа сама тикает с круглым периодом (таймер 10 мс, цикл событий на 100 Гц), профайлер на 100 Гц войдёт с ней в резонанс и будет систематически заставать её в одной фазе. Простое число рядом с круглым ломает синхронизацию. По той же причине вместо 1000 Гц берут 997.

5. Стек: самое хрупкое место конструкции

Сэмпл без стека — это просто адрес инструкции. Он скажет, что программа была в memmove, но не скажет, кто её позвал, а нужно именно это. Разворачивание стека (unwinding) — отдельная нетривиальная задача.

Цепочка frame pointer работает так: регистр RBP указывает на кадр текущей функции, по этому адресу лежит сохранённый RBP вызывающего, рядом — адрес возврата. Обход — цикл из трёх инструкций на кадр, безопасный даже в обработчике NMI. Проблема в том, что двадцать лет -O2 подразумевал -fomit-frame-pointer: регистр освобождался под общие нужды ради нескольких процентов скорости, и цепочка исчезала. Итог — эпоха сломанных стеков, когда flame graph получался плоским и бесполезным.

Индустрия развернулась обратно: Fedora включила фреймпойнтеры по умолчанию с версии 38, Ubuntu — в 24.04; замеры цены (в большинстве нагрузок 0–2%) есть в разборе The Return of the Frame Pointers. Альтернативы: --call-graph dwarf — ядро копирует кусок стека в каждый сэмпл, разворачивание офлайн по .eh_frame, точно, но perf.data пухнет в десятки раз; --call-graph lbr — аппаратный буфер последних переходов, дёшево, но глубина 16–32 кадра; ORC — таблицы разворачивания для кода самого ядра Linux.

nm -C ./api-server | head -5                       # символы вообще есть?
objdump -d ./api-server | grep -A2 -m1 '<main.handleRequest>:'   # пролог сохраняет RBP?

Для C/C++/Rust собирайте профилируемые сборки как -O2 -g -fno-omit-frame-pointer. Символы (-g) лежат в отдельных секциях и не грузятся в память при исполнении — на скорость они не влияют. Выкидывать их из релиза «чтобы бинарь был меньше» — прямой путь к профилю из [unknown] в три часа ночи.

6. Flame graph: как читать и как обманываться

Flame graph, придуманный Бренданом Греггом, — не график и не хронология. Это гистограмма по стекам.

Правила чтения, которые надо заучить:

• Ось X — не время. Ветки отсортированы по алфавиту, чтобы одинаковые профили выглядели одинаково; слева направо ничего не «происходит». Хронологию показывает flame chart — другой инструмент, он есть в Chrome DevTools и speedscope, и вот там ось X действительно время.
• Ширина — доля сэмплов, то есть доля времени, когда этот стек был на CPU. Высота — глубина стека, а не «плохо»: глубокая узкая башня безобидна, широкое плато на любой высоте — ваша цель.
• self (flat) против total (cumulative): первое — время в самом кадре, второе — вместе с потомками. У main всегда 100% cumulative и 0% self. Оптимизировать можно только self, но чинить часто нужно выше по стеку.

Пять способов обмануться, и все пять встречаются в жизни:

1. «Широкая функция — медленная функция». Нет: она может быть быстрой, но вызываемой миллион раз. Ширина — это время, умноженное на частоту. Уточняйте число вызовов инструментированием или по логам.
2. Инлайнинг склеивает кадры. Встроенной функции в стеке нет, её время приписано вызывающей. perf report --inline и DWARF частично восстанавливают картину, но не всегда.
3. Рекурсия ломает интуицию. Она даёт башню в сотни узких кадров; свернуть помогает --reverse (icicle graph растёт от листьев вниз), где все вхождения parse собираются в один широкий корень.
4. Профиль снят не с того. С одного пода из сорока — а тормозит тот, у кого сосед по хосту выел L3. С прогретого процесса — а проблема в первых 30 секундах, пока JIT интерпретирует байткод. Это ровно ошибка выжившего из https://courses.digitable.life/post/performance/02-benchmarking/.
5. Профиль почти пуст, а сервис тормозит. Значит, время уходит не на CPU — см. раздел 10.

git clone --depth 1 https://github.com/brendangregg/FlameGraph
perf record -F 99 -a -g -- sleep 30
perf script | ./FlameGraph/stackcollapse-perf.pl | ./FlameGraph/flamegraph.pl > cpu.svg

# Дифференциальный график: что изменилось между релизами
./FlameGraph/difffolded.pl before.folded after.folded | ./FlameGraph/flamegraph.pl > diff.svg

7. Практика: perf от нуля до картинки

Сначала разрешения — в контейнерах это первая причина пустого профиля:

sudo sysctl -w kernel.perf_event_paranoid=1   # 2-3 = по умолчанию, 1 = плюс ядро, -1 = всё
sudo sysctl -w kernel.kptr_restrict=0         # иначе символы ядра будут как 0x0000
# В Kubernetes нужны CAP_PERFMON (или SYS_ADMIN) и hostPID, чтобы видеть соседние процессы.

Снимаем профиль живого процесса. Идиома -p PID -- sleep 30 означает «профилировать ровно 30 секунд», sleep здесь просто таймер:

$ perf record -F 99 -g --call-graph fp -p $(pgrep -f api-server) -- sleep 30
[ perf record: Woken up 21 times to write data ]
[ perf record: Captured and wrote 5.412 MB perf.data (14806 samples) ]

$ perf report --stdio --no-children --percent-limit 1
# Samples: 14K of event 'cpu-clock:pppH'
#
# Overhead  Command      Shared Object        Symbol
# ........  ...........  ...................  ..........................................
    18.42%  api-server   api-server           [.] encoding/json.(*encodeState).string
    11.07%  api-server   api-server           [.] runtime.mallocgc
     8.93%  api-server   libc.so.6            [.] __memmove_avx_unaligned_erms
     6.51%  api-server   [kernel.kallsyms]    [k] copy_user_enhanced_fast_string
     4.88%  api-server   api-server           [.] regexp.(*machine).add
     3.10%  api-server   api-server           [.] runtime.scanobject

14806 сэмплов на 8 потоков — около 1850 на поток, для кадров от 5% статистика приличная. Ключевой переключатель здесь --no-children (собственное время: кто жжёт CPU) против --children (накопительное: кто виноват в том, что жгут). Смотреть надо оба: первое даёт цель для микрооптимизации, второе — для архитектурного решения. В примере видна типичная для Go картина: сериализация плюс аллокации плюс работа сборщика (scanobject), то есть проблема не в JSON как таковом, а в объёме порождаемого мусора.

perf top -F 99 -g                 # живой профиль, как top для функций
perf annotate --stdio symbol_name # разбивка по инструкциям (осмысленна только с событием :pp)
perf record -e cycles:pp -g ...   # точный режим PEBS
perf record -e cache-misses ...   # профиль не по времени, а по промахам кэша

Последняя строка — недооценённый приём: профилировать можно по любому событию PMU. Профиль по cache-misses показывает не «где программа проводит время», а «где она бьёт по памяти», и это часто совсем другие функции — подробнее в https://courses.digitable.life/post/performance/05-cache-and-locality/.

8. Профайлеры рантаймов: что именно они измеряют

Универсального CPU-профиля не существует: каждый рантайм ставит свои компромиссы, и знать их обязательно.

Safepoint bias заслуживает отдельного слова как самая поучительная история о том, как профайлер уверенно врёт. Работа Evaluating the Accuracy of Java Profilers (Mytkowicz и др., PLDI 2010) показала: четыре популярных Java-профайлера на одной и той же программе называют разных «горячих» лидеров, и как минимум трое ошибаются, потому что сэмплы снимаются только в точках безопасности JVM, а их расстановка коррелирует с оптимизациями JIT. Те же авторы годом раньше в Producing Wrong Data Without Doing Anything Obviously Wrong! показали, что даже размер переменных окружения сдвигает измеряемую производительность на проценты за счёт выравнивания стека. Мораль одна: сверяйте показания двух независимых инструментов, прежде чем принимать решение.

# Go: профиль живого сервиса (import _ "net/http/pprof")
go tool pprof -seconds=30 http://localhost:6060/debug/pprof/profile
go tool pprof -http=:8080 profile.pb.gz            # веб-интерфейс с flame graph и графом вызовов
go tool pprof -diff_base=before.pb.gz after.pb.gz  # что изменилось

py-spy record -o profile.svg --pid 4711 --duration 60 --subprocesses  # Python, без правки кода
./asprof -e cpu -d 30 -f flame.html <pid>          # JVM, async-profiler
./asprof -e wall -t -d 30 -f wall.html <pid>       # wall-clock по потокам: видно ожидания
node --cpu-prof --cpu-prof-dir=./profiles app.js   # Node.js, открывается в DevTools и speedscope
dotnet-trace collect --process-id 1234 --profile cpu-sampling --duration 00:00:00:30

9. Разбор случая: от симптома до подтверждённой починки

История типовая: после релиза p99 на POST /orders вырос с 90 до 340 мс, RPS не изменился, CPU на подах поднялся с 40% до 78%. Маршрут расследования:

Шаг 1 — убедиться, что CPU занят делом, а не ждёт память:

$ perf stat -p $(pgrep -f api-server) -- sleep 10

          7842.19 msec task-clock                #    0.784 CPUs utilized
             1204      context-switches          #  153.53 /sec
    29 731 044 812      cycles                   #    3.791 GHz
    21 402 118 097      instructions             #    0.72  insn per cycle
        69 004 511      branch-misses            #    1.68% of all branches
       412 991 004      cache-misses             #   52.67 M/sec

IPC 0,72 низковат — для скалярного кода ориентир 1,5–2,5, то есть процессор заметную часть времени просто ждёт память. Конкретных виновников perf stat не называет, идём в профиль.

$ go tool pprof -seconds=30 http://api-7f9b:6060/debug/pprof/profile
Type: cpu
Duration: 30s, Total samples = 58.36s (194.53%)

(pprof) top10 -cum
      flat  flat%   sum%        cum   cum%
         0     0%     0%     51.44s 88.14%  net/http.(*conn).serve
         0     0%     0%     49.02s 83.99%  main.(*OrderHandler).ServeHTTP
     0.11s  0.19%  0.19%     31.77s 54.44%  main.enrichOrder
     0.09s  0.15%  0.34%     19.88s 34.07%  main.buildKey
     1.42s  2.43%  2.77%     13.61s 23.32%  regexp.MustCompile
     0.72s  1.23%  5.50%      6.02s 10.31%  runtime.mallocgc

Total samples = 58.36s (194.53%) означает: за 30 секунд стенных часов собрано 58 секунд процессорного времени, то есть в среднем занято около двух ядер. Дальше — list, самая недооценённая команда pprof:

(pprof) list buildKey
ROUTINE ======================== main.buildKey in /srv/api/key.go
     0.09s     19.88s (flat, cum) 34.07% of Total
         .          .     40:func buildKey(userID int64, tags []string) string {
     0.02s     13.61s     41:	re := regexp.MustCompile(`[^a-z0-9]+`)   // <-- компиляция на каждый вызов
         .          .     43:	for _, t := range tags {
     0.04s      4.91s     44:		parts = append(parts, re.ReplaceAllString(t, "-"))
         .          .     46:	return fmt.Sprintf("u%d:%s", userID, strings.Join(parts, "|"))

Диагноз за две минуты: регулярка компилируется на каждый вызов. Это не «медленный regexp» — это неправильное место компиляции.

// Компилируем один раз при инициализации пакета: MustCompile здесь уместен —
// паника на некорректном литерале случится на старте, а не в обработчике запроса.
var nonAlnum = regexp.MustCompile(`[^a-z0-9]+`)

func buildKey(userID int64, tags []string) string {
	var b strings.Builder
	b.Grow(16 + len(tags)*12) // одна аллокация вместо роста буфера в цикле
	b.WriteByte('u')
	b.WriteString(strconv.FormatInt(userID, 10))
	b.WriteByte(':')
	for i, t := range tags {
		if i > 0 {
			b.WriteByte('|')
		}
		b.WriteString(nonAlnum.ReplaceAllString(t, "-"))
	}
	return b.String()
}

Шаг 3 — доказать, что стало лучше, а не поверить. Микробенчмарк (правила честного замера — в https://courses.digitable.life/post/performance/02-benchmarking/), затем benchstat, затем сквозная метрика:

var sink string // пакетная переменная мешает компилятору выбросить вызов целиком

func BenchmarkBuildKey(b *testing.B) {
	tags := []string{"Fast Delivery", "VIP!", "новый клиент"}
	b.ReportAllocs()
	for i := 0; i < b.N; i++ {
		sink = buildKey(int64(i), tags)
	}
}

go test -run='^$' -bench=BuildKey -count=10 ./... > new.txt && benchstat old.txt new.txt

Если p99 после выкатки не сдвинулся — гипотеза была неверна, правку откатываем: профиль показал, где горит, но не гарантировал, что это на критическом пути. Про соотношение локального ускорения и общего выигрыша — закон Амдала в https://courses.digitable.life/post/performance/07-concurrency-performance/.

И главный урок этого разбора: профиль указывает место, а решение почти всегда лежит уровнем выше. Если бы в топе оказалась проверка if x in allowed_list внутри цикла, правильным ответом была бы не микрооптимизация, а замена списка на множество: O(n·m) превращается в O(n+m) времени ценой O(m) памяти, и никакая работа с константой такого не даст. Систематически про это — в https://courses.digitable.life/post/algorithms/18-practical-optimization/.

10. Когда CPU-профиль пуст: off-CPU и wall-clock

Самый частый тупик: сервис отвечает за 800 мс, а профиль показывает почти пустую картинку суммарно на 5% ядра. Причина в том, что CPU-профайлер по определению снимает сэмплы только с потоков в состоянии Running.

Инструменты для остальных двух состояний:

• Off-CPU профиль: offcputime из bcc/bpftrace снимает стек в момент, когда планировщик снял поток с ядра, и складывает время сна по стекам. Методика — Off-CPU Analysis. Получается такой же flame graph, только ширина означает «сколько ждали», а не «сколько считали».
• Wall-clock профиль: async-profiler -e wall, py-spy --idle, для Go — /debug/pprof/goroutine?debug=2. Показывает, где потоки находятся вообще, независимо от состояния.
• Профили блокировок: в Go — runtime.SetBlockProfileRate и SetMutexProfileFraction, дающие /debug/pprof/block и /debug/pprof/mutex; именно они находят контеншн на общем мьютексе.
• Троттлинг cgroup: в Kubernetes поток бывает готов к исполнению, но душится квотой CPU. Смотрите cpu.stat → nr_throttled и throttled_time; профиль при этом выглядит абсолютно нормальным, просто сэмплов мало. Состояния потоков и работа планировщика подробно разобраны в https://courses.digitable.life/post/operating-systems/03-processes-and-scheduling/.

Диагностическое правило: сложите время из CPU-профиля и сравните со стенными часами. Если профиль даёт 0,4 ядра, а запросы идут по 800 мс — вы не в CPU-задаче, и вся эта статья сейчас не поможет; идите в https://courses.digitable.life/post/performance/06-io-and-syscalls/ и https://courses.digitable.life/post/performance/08-database-performance/.

11. Профиль говорит «где», счётчики говорят «почему»

Flame graph показал широкое плато в обходе дерева. Дальше вопрос: функция медленная потому, что делает много работы, или потому, что процессор простаивает на промахах? Ответ дают счётчики PMU — второй измерительный прибор, независимый от первого.

Отдельно стоит знать про Top-down Microarchitecture Analysis: методика раскладывает слоты выдачи инструкций на четыре корзины — Retiring, Bad Speculation, Front-End Bound, Back-End Bound — и сразу говорит, в какой части конвейера проблема. В perf это perf stat --topdown.

И обязательная оговорка про «числа, которые должен знать каждый программист». Знаменитая таблица Джеффа Дина (L1 около 0,5 нс, DRAM около 100 нс, диск около 10 мс) полезна как учебник порядков величин, но её публичные обновления датируются началом 2010-х: NVMe с тех пор ушёл от HDD примерно на два порядка, задержки внутри дата-центра упали, а разрыв между кэшем и DRAM, наоборот, вырос. Пользуйтесь ею как картой масштабов — «сеть в тысячи раз дороже памяти» верно и сегодня, — но никогда как источником констант для расчёта бюджета. Свои числа снимайте на своём железе.

12. Непрерывное профилирование в проде

Профиль, снятый вручную во время инцидента, отвечает на вопрос «что происходит сейчас», но не на вопрос «когда это началось» — а нужно обычно второе. Отсюда практика непрерывного профилирования: агент постоянно снимает короткие профили с низкой частотой, складывает их с метками (версия, под, эндпоинт), и вы можете сравнить сегодня с прошлым вторником. Идея не новая — Google описал внутреннюю систему в работе Google-Wide Profiling ещё в 2010-м, зафиксировав накладные расходы в доли процента. Открытые реализации сегодня — Parca и Grafana Pyroscope, обе на eBPF и обе умеют профилировать процессы без правки кода.

• Бюджет накладных расходов. 19–100 Гц, короткие окна. Проверьте цену экспериментом: включите агент на половине подов и сравните p99 — если разница видна, частота слишком высока.
• Метки. Профиль без версии сборки и имени эндпоинта почти бесполезен. Go умеет pprof.Do(ctx, pprof.Labels("endpoint", "/orders"), fn), и тогда flame graph фильтруется по эндпоинту.
• Символы. Хранилище должно резолвить адреса для каждой версии бинаря: заведите символ-сервер или сохраняйте debuginfo артефактом сборки.
• Безопасность. Профиль — это утечка структуры кода, а иногда и данных. Эндпоинт /debug/pprof никогда не должен смотреть в интернет: отдельный порт, доступный только из кластера. Требования к perf_event_paranoid и CAP_PERFMON — в документации ядра.
• Регрессии. Автоматическое сравнение профиля новой версии с базовой ловит медленно ползущее ухудшение, которое не заметит ни один бенчмарк; как встроить это в конвейер — в https://courses.digitable.life/post/performance/12-optimization-workflow/.

Отдельного упоминания заслуживает каузальное профилирование: Coz (Curtsinger и Berger, SOSP 2015) отвечает не на вопрос «где проводится время», а на вопрос «ускорение какой строки реально ускорит программу»: он виртуально замедляет всё, кроме выбранного участка, и измеряет эффект. Для конкурентного кода, где горячая функция и узкое место — разные вещи, это честнее обычного профиля.

13. Типичные ошибки, стоящие рабочего дня

1. Профилировать debug-сборку. Без оптимизаций это другой код: нет инлайнинга, нет векторизации, аллокации в других местах. Профилируйте релизную сборку с символами.
2. Смотреть только на self. Виновник часто не тот, кто жжёт CPU, а тот, кто зовёт жгущего в цикле.
3. Профилировать без прогрева. Первые секунды JIT-рантайма — профиль интерпретатора, первые минуты БД — профиль холодного кэша. Отбрасывайте разогрев явно.
4. Верить процентам при малом n. 3 сэмпла и 0,2% — это ничто.
5. Оптимизировать самое широкое, не спросив, зачем эта работа делается вообще. Самая быстрая функция — невызванная; кэш, батчинг и убранный лишний вызов регулярно дают больше недели микрооптимизаций.
6. Профилировать один под из ста. Проверьте репрезентативность: тип инстанса, соседи по хосту, шардирование.
7. Останавливаться на первой находке. Убрали 30% — снимайте профиль заново, топ полностью перестроится.
8. Не сохранять профиль. perf.data и .pb.gz — артефакты расследования, складывайте их рядом с тикетом.

Мини-итог

• Профиль — статистическая оценка, а не запись выполнения. У каждой строчки есть доверительный интервал, и он зависит от числа сэмплов в кадре, а не от длительности профилирования как таковой.
• Сэмплирование дёшево и годится для прода; инструментирование точно по числу вызовов, но искажает пропорции и ломает инлайнинг. Начинайте с первого, уточняйте вторым.
• Стек — самое хрупкое звено: -g -fno-omit-frame-pointer, живые символы, при необходимости --call-graph dwarf. Плоский flame graph — почти всегда сломанное разворачивание, а не «простая программа».
• Ось X у flame graph не время. Ширина — доля сэмплов, высота — глубина; ищите широкие плато, смотрите self и cumulative вместе, помните про инлайнинг и рекурсию.
• Пустой CPU-профиль при медленном сервисе — это диагноз, а не сбой: время уходит в off-CPU. Складывайте время профиля и сравнивайте со стенными часами.
• perf stat отвечает «почему медленно» там, где профиль отвечает только «где». IPC ниже единицы — сигнал идти в разговор про кэши и память.
• Числа из чужих таблиц задержек — карта порядков величин, а не источник констант. Измеряйте своё железо, свою нагрузку, достаточно долго.

Источники

• Brendan Gregg. Systems Performance, 2nd ed., Addison-Wesley, 2020; Flame Graphs и репозиторий FlameGraph; Off-CPU Analysis; The Return of the Frame Pointers.
• Linux perf wiki, man-страницы perf-record(1) и perf-stat(1), Perf security model.
• Todd Mytkowicz et al. Evaluating the Accuracy of Java Profilers, PLDI 2010; Producing Wrong Data Without Doing Anything Obviously Wrong!, ASPLOS 2009.
• Gang Ren et al. Google-Wide Profiling, IEEE Micro, 2010; Curtsinger, Berger. Coz: Finding Code that Counts with Causal Profiling, SOSP 2015.
• Profiling Go Programs, пакеты runtime/pprof и net/http/pprof, google/pprof.
• py-spy, async-profiler, speedscope, Parca, Grafana Pyroscope, Top-down Microarchitecture Analysis.
• Смежное на портале: https://courses.digitable.life/post/operating-systems/14-observability-and-performance/ про инструменты Linux, https://courses.digitable.life/post/devops/16-observability-and-oncall/ про наблюдаемость в эксплуатации.

Что дальше

CPU-профиль почти всегда приводит в одно и то же место: аллокации, копирования и работа сборщика мусора. runtime.mallocgc, scanobject, __memmove_avx_unaligned_erms в топе — это не проблема процессора, а проблема памяти, которая просто платится тактами. Следующая статья — про то, как измерять и чинить именно её.

Память: аллокации, фрагментация, утечки, влияние GC