bpftrace на продакшне: ищем задержку в сетевых очередях без остановки сервисов

Звонок пришёл утром в понедельник: у клиента периодически росла латентность на одном из API-узлов, без видимой причины. Prometheus показывал всплески p99 - иногда 200 мс там, где обычно 20. CPU не в панике, памяти хватает, ни один из стандартных метриков даже не моргал. Логи приложения чистые. В прошлом такое расследование превращалось в несколько часов strace, tcpdump и гаданий. На этот раз решили попробовать bpftrace.

Что такое eBPF и почему сейчас

eBPF - это механизм ядра Linux, который позволяет запускать верифицированный байткод прямо в kernelspace, прицепившись к нужным точкам: системным вызовам, функциям ядра, сетевому стеку, планировщику. Никакого патчинга ядра, никаких кастомных модулей - верификатор ядра проверяет программу перед запуском и не даёт ей повесить систему.

BCC (BPF Compiler Collection) существует несколько лет, но именно сейчас инструментарий дорос до того, что его можно без боли тащить на продакшн-хосты: пакеты есть в стандартных репозиториях Ubuntu 18.04 и RHEL 7.6+, bpftrace - высокоуровневый язык поверх BCC - вышел как отдельный проект и сильно снизил порог входа.

Раньше писать BPF-программу означало писать C-код под BCC. Теперь тот же результат можно получить в пять строк на bpftrace.

Как диагностировали

Проблема с периодическими всплесками латентности почти всегда лежит в одном из трёх мест: обработка входящих пакетов в ядре, очереди на сокетах, или что-то на уровне планировщика. Начали с сетевого стека.

bpftrace умеет цепляться к kprobes - точкам входа в функции ядра. Для диагностики очередей SK-buffer интересны функции типа tcp_recvmsg, tcp_sendmsg, и то, как долго пакет висит в очереди приёма до того как приложение его заберёт.

Первый зонд был простым - смотрим время между тем, как пакет появился в очереди, и тем, как приложение вызвало recvmsg:

bpftrace -e '
kprobe:tcp_recvmsg { @start[tid] = nsecs; }
kretprobe:tcp_recvmsg /@start[tid]/
{
  @lat_us = hist((nsecs - @start[tid]) / 1000);
  delete(@start[tid]);
}'

Первые 30 секунд гистограмма выглядела нормально - всё в диапазоне единиц миллисекунд. Потом она резко просела в сторону: несколько вызовов зависли на 150-200 мс. Паттерн был периодическим, примерно раз в несколько десятков секунд.

Что нашли

Это была уже ниточка. Задержка не в сети - пакеты приходили нормально, tcpdump это подтвердил. Задержка была именно в том, когда приложение читало из очереди. Добавили второй зонд - посмотреть на длину backlog очереди в момент задержки:

kretprobe:tcp_recvmsg
/@start[tid] && (nsecs - @start[tid]) > 50000000/
{
  printf("slow recvmsg: pid=%d comm=%s lat_ms=%d\n",
    pid, comm, (nsecs - @start[tid]) / 1000000);
}

В выводе появился comm конкретного процесса - Java-приложение, один конкретный поток. Периодически этот поток просто не читал из сокета. Не потому что сеть медленная, а потому что GC. Garbage collection в JVM останавливал поток как раз в моменты, когда тот должен был читать из сокета. В очереди накапливались пакеты, приложение не успевало - и вот вам p99.

До bpftrace на это ушло бы несколько часов: нужно было бы корреляция GC-логов с tcpdump-трейсами, предположения, перезапуск с флагами GC-логирования... Здесь - десять минут от установки до гипотезы.

Что ещё пробовали

Параллельно посмотрели на несколько готовых BCC-инструментов из коробки. Там целый набор:

• tcplife - показывает жизненный цикл TCP-соединений с длительностью и объёмом данных. Очень удобно когда нужно понять, какие соединения живут долго и почему.
• tcpretrans - отлавливает TCP-ретрансмиссии на уровне ядра, с pid и адресами. То что tcpdump покажет снаружи, это показывает изнутри с контекстом процесса.
• runqlat - задержки в очереди планировщика. Если процесс готов запуститься, но ядро его не берёт - это здесь видно.

runqlat кстати подтвердил косвенно: в моменты GC-паузы тот самый Java-поток не появлялся в очереди планировщика вообще - он был остановлен JVM, а не ожидал CPU.

Что потребовалось для запуска

На хосте с Ubuntu 18.04 и ядром 4.15 bpftrace поставился из PPA одной командой. Никакого перекомпиляния, никакого ребута. Для kprobes нужны права root - это единственное ограничение.

Для RHEL ситуация чуть сложнее: BCC есть в EPEL, но версия может отставать. Ядро должно быть собрано с CONFIG_BPF_SYSCALL и DEBUG_INFO - в RHEL 7.6 это есть по умолчанию.

Важный момент: kprobes цепляются к внутренним функциям ядра, имена которых могут меняться между версиями. То что работает на 4.15, на 4.19 может потребовать правки имён функций. Это не проблема пока работаешь в пределах одного дистрибутива, но при переходе между мажорными версиями - стоит перепроверять.

Где это укладывается в практику

Стандартные инструменты мониторинга - Prometheus, Grafana, всё что мы описывали раньше - работают на метриках, которые кто-то заранее решил собирать. eBPF-трассировка это другой класс инструментов: она отвечает на вопросы, которые вы не успели сформулировать заранее. Прицепиться к любой функции ядра, посмотреть что происходит, отцепиться - и хост даже не заметил.

Для команды это сейчас выглядит как инструмент последней мили при разборе аномалий на продакшне - когда метрики говорят «что-то не так», а что именно - непонятно. Порог входа с bpftrace стал достаточно низким, чтобы не держать это только в голове у одного человека.

BCC и bpftrace мы теперь включаем в стандартный набор диагностических инструментов на серверах клиентов - наряду с perf и strace. Документация ещё не идеальная, готовых рецептов под все случаи нет, но для задач вроде сегодняшней - работает.