Трассировка и профилирование
Предпосылки: режимы CPU и системные вызовы (syscall, ptrace), ELF и линковка (PLT/GOT, символы).
← Терминалы | Загрузка системы →
Production API отвечает за 50 мс, но после очередного деплоя p99 скакнул до 500 мс. Логи молчат — код не изменился, ошибки не выросли. Проблема где-то между приложением и ядром, но где именно? Нужен способ наблюдать за работающим процессом, не модифицируя ни байта его кода. Linux предоставляет целое семейство инструментов для этого — от грубой трассировки каждого системного вызова до программируемых зондов с наносекундным оверхедом (overhead — накладные расходы на само наблюдение).
strace: трассировка системных вызовов
Первый инструмент, к которому обращаются при отладке, — strace. Он показывает каждый системный вызов процесса: имя, аргументы, возвращаемое значение и время выполнения.
ptrace: механизм под капотом
strace работает через системный вызов ptrace(PTRACE_SYSCALL, ...). Процесс-трассировщик (strace) присоединяется к целевому процессу и просит ядро останавливать его дважды на каждом системном вызове — на входе и на выходе. Механизм выглядит так:
целевой процесс ядро 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 (не SIGSTOP), а с опцией PTRACE_O_TRACESYSGOOD — SIGTRAP|0x80, что позволяет strace отличить syscall-stop от обычных сигналов. На один системный вызов приходится четыре переключения контекста (два ptrace-stop и два возобновления). При типичной стоимости переключения контекста в 1-5 микросекунд накладные расходы на один syscall — порядка 10-20 микросекунд. Процесс, выполняющий 100 000 syscall/сек, замедлится с 1 секунды до 2-3 секунд — это и есть те 10-100x замедления, о которых предупреждает документация 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 — это файл конфигурации, который библиотека читает посимвольно вместо fread() с буферизацией. Проблема найдена, но strace на этом исчерпал свои возможности: он видит только границу между user space и kernel space. Всё, что происходит внутри процесса — работу с памятью, кешами CPU, ветвлениями — strace не покажет.
Ограничения strace
Замедление в 10-100 раз делает strace непригодным для production-диагностики высоконагруженных систем. Процесс, обрабатывающий 10 000 запросов в секунду, под strace будет обрабатывать 100-1000. Кроме того, strace видит только системные вызовы. Если процесс медленно работает в user space — считает хеши, сортирует данные, ходит по связным спискам с промахами кеша — strace покажет чистое время в syscall, а остальные 90% процессорного времени останутся невидимыми.
ltrace: трассировка библиотечных вызовов
Между пользовательским кодом и системными вызовами находится ещё один слой — библиотечные функции. Программа вызывает malloc(), printf(), strlen(), SSL_read(), а те внутри себя совершают один или несколько системных вызовов. ltrace перехватывает вызовы на этом уровне — на границе динамической линковки.
Механизм работы похож на strace — тоже через ptrace, но точка перехвата другая. ltrace загружает ELF-файл (Executable and Linkable Format) целевого процесса, находит PLT (Procedure Linkage Table) и через PTRACE_POKETEXT записывает инструкцию int3 (breakpoint, 0xCC) в каждую PLT-запись. Когда процесс вызывает библиотечную функцию и попадает на breakpoint, ядро генерирует SIGTRAP, процесс останавливается в ptrace-stop, и ltrace получает управление. ltrace читает аргументы из регистров, восстанавливает оригинальную инструкцию в PLT, продолжает выполнение до возврата из функции (через аналогичный breakpoint) и записывает результат.
ltrace -e malloc+free -p 12345Вывод покажет каждый malloc() с размером запрашиваемой памяти и каждый free() с адресом:
malloc(4096) = 0x55a3c8001200
malloc(64) = 0x55a3c8002400
free(0x55a3c8001200) = <void>
malloc(4096) = 0x55a3c8001200
Замедление от ltrace — порядка 5-50x. Механизм тот же, что у strace (ptrace + остановка процесса), но библиотечные вызовы обычно реже системных: программа может делать 100 000 syscall/сек, но только 10 000 вызовов malloc/сек — отсюда меньшее суммарное замедление. Но всё равно слишком много для production-нагрузки.
ltrace полезен в конкретных ситуациях: когда нужно понять, как часто программа выделяет и освобождает память, какие строковые операции доминируют, сколько раз вызывается dlopen() при загрузке плагинов. Но он работает только с динамически слинкованными библиотеками — статически слинкованный бинарник для ltrace невидим.
perf stat: аппаратные счётчики производительности
strace показал 4000 лишних read(), мы их исправили, но p99 всё ещё 300 мс вместо 50. Проблема сместилась куда-то внутрь user space, где strace слеп. Нужен инструмент, который видит, как процессор выполняет код — не на уровне системных вызовов, а на уровне инструкций, тактов и кешей.
PMU: счётчики внутри процессора
Каждый современный процессор содержит PMU (Performance Monitoring Unit) — блок из 4-8 программируемых аппаратных счётчиков. Каждый счётчик — это регистр, который автоматически инкрементируется при наступлении определённого события: выполнена инструкция, пройден такт, произошёл промах кеша L1, неправильно предсказано ветвление. Счётчики работают параллельно с основной логикой процессора и не замедляют исполнение — они читают уже существующие сигналы внутри конвейера.
Ядро 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 (Instructions Per Cycle) = 0.3 — процессор тратит 3.3 такта на одну инструкцию. Для типичного серверного кода IPC 1.0-2.0 считается нормой (современные процессоры могут выполнять 4-6 инструкций за такт при идеальных условиях). IPC 0.3 означает, что процессор почти всё время простаивает в ожидании данных. 40% промахов кеша подтверждают гипотезу: код ходит по памяти непредсказуемо, каждый промах L3 стоит 50-100 наносекунд, и конвейер останавливается.
Оверхед perf stat практически нулевой — он читает значения аппаратных регистров в начале и конце интервала. Процесс не останавливается, не замедляется, не знает о наблюдении. Это принципиальное отличие от strace: PMU-счётчики существуют в кремнии и работают всегда, perf stat лишь читает их значения.
perf record/report: сэмплирующий профилировщик
perf stat показал, что проблема — в промахах кеша, но не показал, где в коде они происходят. Нужно найти конкретные функции.
Принцип семплирования
perf record работает по принципу статистического семплирования (sampling — периодическая выборка состояния процессора). PMU программируется на генерацию прерывания каждые N событий (например, каждые 100 000 тактов или каждые 10 000 промахов кеша). Когда счётчик переполняется, процессор генерирует NMI (Non-Maskable Interrupt), ядро записывает текущий 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), и при срабатывании управление попадает в 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: однострочники для трассировки
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 микросекунд. Второй пик — соединения к реплике БД в соседней зоне доступности. Одна из реплик стала отвечать медленнее, и запросы, попавшие на неё, получают дополнительные 100-200 микросекунд на каждое TCP-подключение. При 50 запросах к БД на один API-вызов это превращается в 5-10 мс дополнительной задержки.
Ещё несколько полезных однострочников:
Подсчёт системных вызовов по процессам за 5 секунд:
bpftrace -e 'tracepoint:raw_syscalls:sys_enter { @[comm] = count(); }' -d 5Распределение задержек блочного ввода-вывода:
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, который срабатывает 1000 раз в секунду, дополнительная нагрузка — наносекунды. На hot path (горячем пути — часто выполняемом участке кода) системного вызова при 100 000 срабатываний/сек оверхед может достигать 1-3%. Это на два порядка меньше strace и достаточно безопасно для production.
GDB и ptrace: интерактивная отладка
Все предыдущие инструменты наблюдают за процессом, не останавливая его (кроме strace, который останавливает на каждом syscall). GDB (GNU Debugger) занимает противоположную нишу — он полностью останавливает процесс и даёт исследовать его состояние.
Механизм точек останова
GDB использует тот же ptrace(), что и strace, но с другими командами. Для установки breakpoint GDB выполняет ptrace(PTRACE_PEEKDATA, ...), чтобы прочитать оригинальный байт по целевому адресу, сохраняет его, и записывает на это место 0xCC — инструкцию int3 (software interrupt). Когда процессор доходит до этого адреса, инструкция 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... -------| |
DWARF: от адресов к именам
Без отладочной информации GDB видит только адреса: 0x4011a0, 0x401230, 0x7fff2a3b1000. Чтобы показать имена переменных, номера строк исходного кода и структуру типов, компилятор встраивает в бинарник секцию DWARF (Debugging With Attributed Record Formats — формат отладочной информации). Эта секция содержит маппинг: адрес 0x4011a0 соответствует файлу main.c, строке 42, функции process_request; переменная count лежит по смещению -8(%rbp) и имеет тип int.
DWARF-информация увеличивает размер бинарника в 2-10 раз (production-бинарник Go на 100 МБ может содержать 300 МБ отладочных данных). Поэтому в 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 перехватывает системные вызовы — границу между приложением и ядром. Замедление 10-100x делает его инструментом для разработки и стейджинга, но не для production. Типичная задача: «процесс не может открыть файл — какой путь он пытается открыть?».
ltrace перехватывает вызовы динамических библиотек через PLT. Замедление 5-50x. Полезен, когда нужно понять паттерн вызовов malloc/free или какие функции OpenSSL используются при TLS-рукопожатии (Transport Layer Security).
perf stat читает аппаратные счётчики PMU — инструкции, такты, промахи кеша, неправильные предсказания ветвлений. Оверхед практически нулевой. Отвечает на вопрос «процессор загружен, но чем?» на уровне микроархитектуры.
perf record семплирует стеки вызовов по событиям PMU. Оверхед менее 1% при стандартных настройках. Находит горячие функции и строит flame graphs. Не видит отдельные события — только статистическую картину.
eBPF/bpftrace выполняет произвольную программу при наступлении события — syscall, вход в функцию ядра или user space, tracepoint, аппаратное событие. Оверхед наносекундный на одно срабатывание. Единственный инструмент, который может строить гистограммы задержек отдельных операций в production.
GDB останавливает процесс и даёт полный доступ к его состоянию: регистры, память, стеки всех потоков. Незаменим для post-mortem анализа core dumps, непригоден для наблюдения за живой production-нагрузкой.
Для диагностики спайка p99 путь выглядит так: strace -c для быстрой проверки паттерна 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
← Терминалы | Загрузка системы →