Трассировка и профилирование
Предпосылки: режимы CPU и системные вызовы (syscall), ELF и линковка (PLT/GOT, символы), процессор (конвейер, IPC, суперскалярное исполнение), иерархия памяти (кеш-иерархия, промахи кеша, задержки).
← Терминалы | Загрузка системы →
Production API отвечает за 50 мс, но после очередного деплоя p99 скакнул до 500 мс. Логи молчат — код не изменился, ошибки не выросли. Проблема где-то между приложением и ядром, но где именно? Нужен способ наблюдать за работающим процессом, не модифицируя ни байта его кода.
strace: трассировка системных вызовов
Первый инструмент, к которому обращаются при отладке, — strace. Он показывает каждый системный вызов процесса: имя, аргументы, возвращаемое значение и время выполнения.
strace -c: агрегированная статистика
Для начала диагностики удобнее не поток отдельных вызовов, а общая картина. Подключаемся к процессу API-сервера:
strace -c -p 12345Флаг -c собирает статистику без вывода каждого вызова. После Ctrl+C strace покажет сводку:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- -------
62.14 0.408231 98 4163 read
18.50 0.121568 29 4098 write
11.24 0.073912 18 4098 epoll_wait
5.88 0.038651 37 1024 recvfrom
2.24 0.014725 14 1024 sendto
4163 вызова read() за несколько секунд — при ожидаемых ~400. Кто-то читает по мелким порциям вместо одного большого буфера. Флаг -e trace=read покажет каждый вызов с аргументами:
strace -e trace=read -p 12345В выводе видно read(7, "...", 1) — чтение по одному байту из дескриптора 7. Дескриптор 7 — файл конфигурации, который открывается без буферизации. Добавляем в код буферизованное чтение — p99 падает с 500 мс до 300 мс. Прогресс, но до целевых 50 мс ещё далеко.
Запускаем strace -c снова и видим другую аномалию:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- -------
48.12 0.312480 14 3217 brk
31.07 0.201645 98 2041 mmap
12.18 0.079012 19 4098 write
8.63 0.056011 14 4098 epoll_wait
3217 вызовов brk() — системный вызов расширения кучи — за 10 секунд наблюдения. Для сервиса, который обычно делает десятки brk() за такой интервал, это аномалия. strace видит симптом: процесс активно просит у ядра новую память. Но кто именно выделяет и почему столько — стоит за границей, которую strace не видит: он перехватывает только системные вызовы на границе между пространством пользователя (user space) и ядром (kernel space), а не вызовы библиотек внутри процесса.
ptrace: механизм под капотом
Почему strace так сильно замедляет процесс? Цена скрыта в механизме ptrace — системном вызове, через который работают все отладчики. Процесс-трассировщик (strace) присоединяется к целевому процессу командой ptrace(PTRACE_SYSCALL, ...) и просит ядро останавливать его дважды на каждом системном вызове — на входе и на выходе. Механизм выглядит так:
целевой процесс ядро strace
| | |
|--- syscall ----------->| |
| (read) |--- syscall-enter ---->|
| [ptrace-stop] | (SIGTRAP) |
| |<-- PTRACE_GETREGS ---|
| | (читает rax, |
| | rdi, rsi, rdx) |
| |<-- PTRACE_SYSCALL ---|
|<-- продолжить ---------| |
|--- syscall return ---->| |
| [ptrace-stop] |--- syscall-exit ----->|
| | (SIGTRAP) |
| |<-- PTRACE_GETREGS ---|
| | (читает rax = |
| | return value) |
| |<-- PTRACE_SYSCALL ---|
|<-- продолжить ---------| |
Каждая остановка — ptrace-stop: ядро замораживает целевой процесс и уведомляет strace через waitpid(). Статус остановки обозначается как SIGTRAP — сигнал-ловушка, который ядро доставляет трассировщику при каждом syscall-stop и breakpoint. С опцией PTRACE_O_TRACESYSGOOD статус становится SIGTRAP|0x80, что позволяет strace отличить syscall-stop от обычных сигналов. На каждом вызове strace читает аргументы (PTRACE_GETREGS), форматирует вывод, копирует строковые буферы из памяти процесса — всё это сверх самих переключений контекста. В итоге накладные расходы составляют порядка 10-100x замедления (Brendan Gregg в реальных тестах наблюдал свыше 100x). Кроме того, strace также не видит библиотечные вызовы — только границу с ядром.
Замедление делает strace непригодным для production-диагностики высоконагруженных систем. Если же нужно снизить оверхед при выборочной трассировке, начиная со strace v5.3 доступен флаг --seccomp-bpf, который вдвое сокращает количество переходов в ядро для нетрассируемых вызовов.
ltrace: трассировка библиотечных вызовов
strace показал аномалию brk(), но не показал источник. ltrace перехватывает вызовы на уровень выше — на границе динамической линковки. Смотрим, кто вызывает malloc():
ltrace -e malloc+free -p 12345В выводе виден паттерн:
malloc(18) = 0x55a3c8012340
malloc(12) = 0x55a3c8012360
malloc(7) = 0x55a3c8012380
malloc(23) = 0x55a3c80123a0
malloc(5) = 0x55a3c80123c0
Сотни мелких аллокаций от 5 до 30 байт на каждый API-запрос. Добавив фильтрацию по имени библиотеки, видим, что источник — libjson-c.so: парсер выделяет отдельную строку для каждого ключа и значения в JSON-ответе. При ответах по 50 полей это 100+ мелких malloc() на запрос, каждый выравнивается и обслуживается аллокатором через brk() когда арена заполнена. Направление расследования ясно: нужен JSON-парсер с поддержкой арены или пул строк.
Механизм ltrace работает на уровне динамической линковки. ltrace загружает ELF-файл целевого процесса, находит PLT (Procedure Linkage Table — таблица, через которую проходят все вызовы динамических функций) и через PTRACE_POKETEXT записывает инструкцию int3 (0xCC) в каждую PLT-запись. int3 — однобайтовая x86-инструкция «программный breakpoint»: когда процессор её выполняет, он генерирует исключение Breakpoint (#BP), ядро превращает его в SIGTRAP и уведомляет ltrace через ptrace-stop. ltrace читает аргументы из регистров, восстанавливает оригинальную инструкцию в PLT, продолжает выполнение до возврата из функции и записывает результат.
Замедление от ltrace — порядка нескольких десятков раз на высокочастотных вызовах: механизм тот же, что у strace (ptrace + остановка процесса). Для разовой диагностики в staging это приемлемо. ltrace работает только с динамически слинкованными библиотеками — статически слинкованный бинарник для ltrace невидим.
ltrace показал направление — парсер, но не точку. p99 держится на 300 мс: где именно процессор тратит время? strace и ltrace перехватывают вызовы на границах, но не видят, что происходит между ними — внутри самого кода. Нужен инструмент, который читает аппаратные счётчики без остановки процесса.
perf stat: аппаратные счётчики производительности
PMU: счётчики внутри процессора
PMU (Performance Monitoring Unit) — аппаратный блок процессора с программируемыми регистрами-счётчиками событий: инструкции, такты, промахи кеша, неправильные предсказания ветвлений. Счётчики работают параллельно с основной логикой процессора и не замедляют исполнение.
Ядро Linux предоставляет доступ к PMU через системный вызов perf_event_open(). Он принимает описание события (какой тип — hardware, software, tracepoint — и конкретное событие), целевой PID и CPU, и возвращает файловый дескриптор. Через этот дескриптор можно читать текущее значение счётчика или настроить его на генерацию прерывания при переполнении (sampling). Утилита perf — command-line интерфейс к этому вызову.
perf stat: нулевой оверхед
Запускаем perf stat на работающем процессе:
perf stat -p 12345 sleep 5За 5 секунд perf stat прочитает аппаратные счётчики и покажет:
Performance counter stats for process id '12345':
8,241.52 msec task-clock
12,482,319,405 instructions # 0.30 insn per cycle
41,607,731,350 cycles
2,846,219,000 cache-references
1,138,487,600 cache-misses # 40.0% of all cache refs
584,371,000 branch-misses
IPC = 0.3 — процессор почти всё время простаивает в ожидании данных. 40% промахов кеша подтверждают гипотезу: код ходит по памяти непредсказуемо, каждый промах L3 стоит 80–120 наносекунд суммарно, и конвейер останавливается.
Оверхед perf stat практически нулевой — он читает значения аппаратных регистров в начале и конце интервала. Процесс не останавливается, не замедляется, не знает о наблюдении. Это принципиальное отличие от strace: PMU-счётчики существуют в кремнии и работают всегда, perf stat лишь читает их значения.
perf record/report: сэмплирующий профилировщик
perf stat показал, что проблема — в промахах кеша, но не показал, где в коде они происходят. Нужно найти конкретные функции.
Принцип семплирования
perf record работает по принципу статистического семплирования (sampling — периодическая выборка состояния процессора). PMU программируется на генерацию прерывания каждые N событий (например, каждые 100 000 тактов или каждые 10 000 промахов кеша). Когда счётчик переполняется, процессор генерирует NMI и ядро записывает текущий RIP (instruction pointer) и, опционально, стек вызовов. За 10 секунд профилирования накапливаются тысячи семплов. Функции, в которых процессор провёл больше времени, попадутся в семплах чаще.
perf record -g -p 12345 -- sleep 10Флаг -g включает запись стеков вызовов (call graphs). Без него perf покажет только «горячие» функции, но не покажет, кто их вызывал. Результат сохраняется в файл perf.data.
perf report Overhead Command Shared Object Symbol
........ ........ ................. ........................
28.41% api libpq.so [.] PQgetResult
15.32% api libc.so.6 [.] __memcpy_avx2
12.18% api api [.] parse_json_payload
9.74% api api [.] hash_lookup
8.11% api [kernel] [k] copy_user_generic
28% времени — в PQgetResult (ожидание ответа от PostgreSQL), 15% — в memcpy (копирование данных), 12% — в парсинге JSON. Но perf report показывает плоский список. Для сложных иерархий вызовов удобнее другая визуализация.
Flame graphs
Flame graph (граф пламени) — визуальное представление стеков вызовов, где ширина каждого прямоугольника пропорциональна количеству семплов. Стеки растут снизу вверх: внизу — main(), вверху — функция, где процессор находился в момент семпла. Широкие «плато» наверху — горячие функции, которые стоит оптимизировать.
perf script | stackcollapse-perf.pl | flamegraph.pl > flame.svgСкрипты stackcollapse-perf.pl и flamegraph.pl из набора инструментов Brendan Gregg преобразуют вывод perf script в SVG (Scalable Vector Graphics) — интерактивный векторный формат: в браузере можно кликать на секции, чтобы «зумить» в конкретную ветку вызовов.
Оверхед perf record зависит от частоты семплирования. По умолчанию — 4000 семплов в секунду, что добавляет менее 1% нагрузки. При агрессивном профилировании (100 000 семплов/сек) оверхед может вырасти до 2-5%, но это всё ещё на порядки меньше strace.
eBPF: программируемая трассировка ядра
perf нашёл горячие функции, мы оптимизировали парсинг JSON, но часть запросов всё ещё медленная. perf показывает агрегированную картину — средние значения за период. А нужно понять, почему конкретные запросы медленные. Нужен инструмент, который может измерять задержку каждого отдельного события и строить распределение в реальном времени.
Архитектура eBPF
eBPF (extended Berkeley Packet Filter) — виртуальная машина внутри ядра Linux. Программа на eBPF — это байткод (промежуточное представление программы, которое выполняет виртуальная машина внутри ядра, а не процессор напрямую), который загружается в ядро и выполняется при наступлении определённого события. В отличие от модулей ядра, eBPF-программы безопасны по конструкции: перед загрузкой верификатор (verifier) проверяет каждую программу на отсутствие бесконечных циклов, выхода за границы памяти и обращений к запрещённым областям.
Верификатор работает как статический анализатор. Он проходит по каждому возможному пути выполнения программы и проверяет: все циклы имеют гарантированный верхний предел итераций (до ядра 5.3 циклы были запрещены полностью), каждое обращение к памяти проверено на границы, программа завершается за конечное число шагов (лимит — 1 млн шагов верификатора; при ветвлениях каждый путь считается отдельно, поэтому небольшая программа с глубокими ветвлениями исчерпывает лимит быстрее, чем линейная программа в тысячу инструкций). Если хотя бы одна проверка не пройдена, ядро отказывается загружать программу.
eBPF-программы могут подключаться к разным точкам в системе:
kprobe (kernel probe — зонд ядра) — зонд на входе в любую функцию ядра. Ядро заменяет первый байт инструкции на int3 (0xCC, на x86), и при срабатывании управление попадает в eBPF-программу, которая читает аргументы функции. kretprobe делает то же на выходе из функции, позволяя измерить время выполнения.
uprobe (user-space probe — зонд пользовательского пространства) — аналог kprobe для user-space функций. Ядро модифицирует код процесса в памяти, подставляя int3. При срабатывании процесс переходит в ядро, выполняется eBPF-программа, и управление возвращается. Оверхед одного uprobe — порядка 1-5 микросекунд.
tracepoint (точка трассировки) — статическая точка трассировки, вкомпилированная разработчиками ядра в определённых местах кода: вход/выход из syscall, события планировщика, сетевые события. В отличие от kprobe, tracepoint имеет стабильный ABI и не ломается при обновлении ядра.
perf_event — подключение к аппаратным счётчикам PMU, как в perf record, но с возможностью программной обработки каждого семпла.
bpftrace: однострочники для трассировки
Писать eBPF-программу на C и загружать её через libbpf для одноразовой диагностики неудобно. bpftrace — высокоуровневый язык для написания eBPF-программ, аналогичный awk по духу: короткие скрипты без компиляции и загрузки вручную. Вернёмся к проблеме с API — нужно измерить задержку TCP-соединений:
bpftrace -e 'kprobe:tcp_v4_connect { @start[tid] = nsecs; }
kretprobe:tcp_v4_connect /@start[tid]/ {
@usecs = hist((nsecs - @start[tid]) / 1000);
delete(@start[tid]);
}'Скрипт ставит kprobe на вход в tcp_v4_connect (запоминает время) и kretprobe на выход (считает разницу). Результат — гистограмма задержек в микросекундах:
@usecs:
[0] 0 | |
[1] 0 | |
[2, 4) 12 |@@ |
[4, 8) 187 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8, 16) 42 |@@@@@@@@ |
[16, 32) 15 |@@@ |
[32, 64) 3 |@ |
[64, 128) 89 |@@@@@@@@@@@@@@@@@@ |
[128, 256) 67 |@@@@@@@@@@@@@@ |
[256, 512) 23 |@@@@@ |
Распределение бимодальное: основная масса подключений — 4-8 микросекунд (локальные или в пределах одного датацентра), но есть второй пик на 64-256 микросекунд. Второй пик — соединения к реплике БД в соседней зоне доступности (availability zone — изолированная часть датацентра или отдельный датацентр). Одна из реплик стала отвечать медленнее, и запросы, попавшие на неё, получают дополнительные 100-200 микросекунд на каждое TCP-подключение. При 50 запросах к БД на один API-вызов это превращается в 5-10 мс дополнительной задержки.
Ещё несколько полезных однострочников:
Подсчёт системных вызовов по процессам (bpftrace работает до прерывания, поэтому ограничиваем 5 секундами вручную):
bpftrace -e 'tracepoint:raw_syscalls:sys_enter { @[comm] = count(); }' & sleep 5; kill -INT $!Распределение задержек блочного ввода-вывода:
bpftrace -e 'tracepoint:block:block_rq_issue { @start[args->dev, args->sector] = nsecs; }
tracepoint:block:block_rq_complete /@start[args->dev, args->sector]/ {
@usecs = hist((nsecs - @start[args->dev, args->sector]) / 1000);
delete(@start[args->dev, args->sector]);
}'Оверхед eBPF зависит от типа зонда и частоты срабатывания. kprobe и tracepoint при 1000 срабатываниях в секунду добавляют сотни наносекунд на вызов. uprobe дороже — порядка 1-5 мкс на срабатывание, потому что требует перехода между пространством пользователя и ядром. На hot path (горячем пути — часто выполняемом участке кода) системного вызова при 100 000 срабатываний/сек оверхед kprobe может достигать 1-3%. Это на два порядка меньше strace и достаточно безопасно для production.
GDB и ptrace: интерактивная отладка
Если вместо деградации p99 процесс падает с segfault или зависает, цепочка «strace → ltrace → perf → bpftrace» не поможет — нужен полный снимок состояния. GDB (GNU Debugger) занимает эту нишу: он полностью останавливает процесс и даёт исследовать его состояние — регистры, память, стеки всех потоков.
Механизм точек останова
GDB использует тот же ptrace(), что и strace, но с другими командами. Для установки breakpoint GDB выполняет ptrace(PTRACE_PEEKDATA, ...), чтобы прочитать оригинальный байт по целевому адресу, сохраняет его, и записывает на это место 0xCC — инструкцию int3. Когда процессор доходит до этого адреса, int3 генерирует исключение BP (Breakpoint), ядро доставляет SIGTRAP процессу, ptrace перехватывает его и будит GDB. GDB читает регистры (PTRACE_GETREGS), память (PTRACE_PEEKDATA) и показывает текущую позицию в коде.
GDB ядро процесс
| | |
|-- PTRACE_POKEDATA -------->| |
| addr=0x4011a0 |-- пишет 0xCC --------->|
| data=0xCC | по адресу 0x4011a0 |
| | |
|-- PTRACE_CONT ------------>| |
| |-- возобновляет ------->|
| | |
| | [процесс доходит |
| | до 0x4011a0] |
| | |
| |<-- int3 (#BP) ---------|
|<-- SIGTRAP ----------------| |
| | [остановлен] |
|-- PTRACE_GETREGS --------->| |
|<-- rip, rsp, rax... -------| |
После остановки GDB знает адрес, но не знает имён — только 0x4011a0. Чтобы показать имена переменных, номера строк и функции, нужна дополнительная информация.
DWARF: от адресов к именам
DWARF (Debugging With Attributed Record Formats — формат отладочной информации) — секция ELF-файла, которую компилятор создаёт при сборке с отладочными символами. Она содержит маппинг: адрес 0x4011a0 соответствует файлу main.c, строке 42, функции process_request; переменная count лежит по смещению -8 от основания стека текущего фрейма и имеет тип int.
DWARF-информация значительно увеличивает размер бинарника — часто кратно, а в проектах с глубокой шаблонной иерархией (C++) отладочные секции могут занимать большую часть файла. Поэтому в production часто используют stripped-бинарники без DWARF, а отладочные символы хранят отдельно (debug packages: *-dbg в Debian, *-debuginfo в RHEL — Red Hat Enterprise Linux). GDB умеет загружать символы из отдельного файла по Build ID (идентификатор сборки) — уникальному хешу, вшитому при компиляции.
Ограничения GDB в production
GDB останавливает процесс полностью — все потоки замораживаются до команды continue. Для production-сервера это означает полное прекращение обслуживания. Даже single-step (пошаговое исполнение) одного потока в многопоточном приложении вызывает заметные задержки: GDB по умолчанию останавливает все потоки при срабатывании breakpoint (режим all-stop). Существует режим non-stop, при котором останавливается только поток, попавший на breakpoint, но другие потоки могут изменить разделяемое состояние, что усложняет отладку.
GDB незаменим для post-mortem анализа: когда процесс уже упал и оставил core dump (файл со снимком памяти и состояния процесса на момент падения). Команда gdb /path/to/binary /path/to/core загружает образ памяти и позволяет исследовать стек вызовов (bt), значения переменных (print), содержимое структур данных — всё на момент падения.
Сравнение инструментов
Каждый инструмент видит свой срез системы, и ни один не заменяет остальные.
strace перехватывает системные вызовы — границу между приложением и ядром. Замедление >100x (на syscall-heavy нагрузке) делает его инструментом для разработки и стейджинга (staging — промежуточная среда, приближённая к production), но не для production. Типичная задача: «процесс не может открыть файл — какой путь он пытается открыть?».
ltrace перехватывает вызовы динамических библиотек через PLT. Замедление сопоставимо со strace на высокочастотных вызовах. Полезен, когда strace показал подозрительный паттерн системных вызовов, но источник — внутри библиотеки: какая функция libconfig делает тысячи read(), какой паттерн аллокаций у malloc/free, какие функции OpenSSL участвуют в TLS-рукопожатии.
perf stat читает аппаратные счётчики PMU — инструкции, такты, промахи кеша, неправильные предсказания ветвлений. Оверхед практически нулевой. Отвечает на вопрос «процессор загружен, но чем?» на уровне микроархитектуры.
perf record семплирует стеки вызовов по событиям PMU. Оверхед менее 1% при стандартных настройках. Находит горячие функции и строит flame graphs. Не видит отдельные события — только статистическую картину.
eBPF/bpftrace выполняет произвольную программу при наступлении события — syscall, вход в функцию ядра или user space, tracepoint, аппаратное событие. Оверхед kprobe/tracepoint — сотни наносекунд на срабатывание; uprobe — 1-5 микросекунд. Единственный инструмент, который может строить гистограммы задержек отдельных операций в production.
GDB останавливает процесс и даёт полный доступ к его состоянию: регистры, память, стеки всех потоков. Незаменим для post-mortem анализа core dumps, непригоден для наблюдения за живой production-нагрузкой.
Для диагностики спайка p99 путь выглядит так: strace -c для быстрой проверки паттерна syscall, ltrace если syscall-паттерн указывает на библиотеку, perf stat для оценки IPC и промахов кеша, perf record -g для нахождения горячих функций, bpftrace для построения распределения задержек конкретных операций. Каждый следующий инструмент видит глубже предыдущего, но и требует больше экспертизы для интерпретации результатов.
Sources
- Brendan Gregg, 2019, BPF Performance Tools — Addison-Wesley — https://www.brendangregg.com/bpf-performance-tools-book.html
man 1 strace— https://man7.org/linux/man-pages/man1/strace.1.htmlman 1 perf— https://man7.org/linux/man-pages/man1/perf.1.htmlman 2 ptrace— https://man7.org/linux/man-pages/man2/ptrace.2.htmlman 2 perf_event_open— https://man7.org/linux/man-pages/man2/perf_event_open.2.html
← Терминалы | Загрузка системы →