strace: трассировка системных вызовов для диагностики зависаний и утечек

03.09.2026 Раздел: Посты Слов: 776 4 мин

Lead DevOps

При зависании сервиса стандартные инструменты — top, htop, ps — показывают состояние, но не причину. Если процесс в state D (uninterruptible sleep), значит он ждёт syscall. strace подключается к живому процессу и выводит каждый системный вызов в реальном времени. Это превращает загадочное зависание в конкретный syscall, его аргументы и код возврата.

Примечание

strace работает через ptrace — механизм ядра для отладки. На продакшене трассировка замедляет процесс в 2–10 раз. Используйте точечно, на отдельном PID.

Базовые флаги и синтаксис

Установка:

# Debian/Ubuntu
apt install strace

# RHEL/CentOS
yum install strace

# Alpine
apk add strace

Запуск:

# Трассировка нового процесса
strace ls -la /tmp

# Подключение к работающему процессу
strace -p 12345

# Подключение с подпроцессами (fork/clone)
strace -fp 12345

Основные флаги для диагностики:

Флаг	Назначение
`-f`	Следить за дочерними процессами
`-c`	Подсчёт вызовов и времени (summary)
`-tt`	Микросекундные метки времени
`-T`	Время выполнения каждого syscall
`-e trace=openat,read,write`	Трассировать только указанные вызовы
`-e write=1,2`	Трассировать запись только в fd 1 и 2
`-o output.log`	Запись в файл
`-s 1024`	Обрезать строки длиннее N символов

Диагностика блокирующих вызовов

Сценарий: процесс завис, в ps видите state D. Нужно понять, на чём именно он заблокирован.

# Смотрим статус процесса
ps aux | grep nginx
# root     12345  0.0  0.1 ... S    pts/0    0:00 nginx: worker

# Подключаемся на 5 секунд, выводим всё
strace -p 12345 -f -tt -T 2>&1 | head -50

Типичный вывод при блокировке на файле:

14:23:45.123456 read(15, "", 1024)  = 0 <2.345678>
14:23:47.469134 openat(AT_FDCWD, "/var/data/large-file.db", O_RDONLY) = 15 <0.000023>
14:23:47.469157 read(15, "", 1024)  = 0 <5.678901>

Если видите read(...) <время> = 0 с большим временем — процесс ждёт данных. Если <время> исчисляется секундами, нашли bottleneck.

Подсказка

Блокировка на epoll_wait, poll, select — нормально для idle-процесса. Ищите read, write, openat, sendto с временем больше 100ms.

Для сетевых сокетов полезно:

# Трассируем только сетевые вызовы
strace -p 12345 -e trace=network,read,write -f

Зависание на connect() к недоступному хосту:

14:30:01.234 connect(14, {sa_family=AF_INET, sin_port=htons(5432), sin_addr=inet_addr("10.0.0.100")}, 16) = -1 EINPROGRESS <3.456789>

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

Поиск утечек файловых дескрипторов

Сценарий: процесс не открывает файлы, ошибка “too many open files”. Нужно понять, кто держит дескрипторы.

# Смотрим лимиты и текущее использование
ps aux | grep myservice
# 12345  5123  0.0  /opt/myservice

cat /proc/12345/limits | grep "Max open files"
# Max open files            1024                 1024                 files

# Подсчёт открытых fd
ls /proc/12345/fd | wc -l
# 987

Подключаем strace с фильтром на открытие файлов:

strace -p 12345 -e trace=openat,open,close,clone -f 2>&1 | tee /tmp/strace.log

Анализируем вывод:

# Что открывалось и не закрывалось
grep -E "openat|close" /tmp/strace.log | awk '{print $2}' | sort | uniq -c | sort -rn | head -20

Альтернатива — summary mode:

# Статистика за 30 секунд
timeout 30 strace -p 12345 -c -f 2>&1

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 45.23    1.234567          123       1000         openat
 30.12    0.823456           45      18234       close
 20.45    0.559123         8905        63         read
------ ----------- ----------- --------- --------- -------
100.00    2.617146               19297        63 total

Если close вызывается меньше openat — нашли утечку.

Предупреждение

При высокой частоте вызовов (тысячи в секунду) strace генерирует огромный вывод. Ограничивайте время -tt и фильтруйте по syscall через -e trace=.

Анализ медленных запросов

Сценарий: API- endpoint отвечает 5 секунд вместо 200ms. Нужно найти, на каком syscall теряется время.

# Запускаем процесс и трассируем с таймингами
strace -f -tt -T -o /tmp/slow.log ./myservice

# Или подключаемся к работающему
strace -p 12345 -f -tt -T 2>&1 | tee /tmp/live.log

Ищем вызовы с большим временем выполнения:

# Выделяем syscall с временем больше 500ms
grep -E "\> [0-9]\.[0-9]{3}" /tmp/live.log | sort -t '>' -k2 -rn | head -20

14:45:23.123456 write(7, "HTTP/1.1 200 OK\r\n"..., 512) = 512 <0.000045>
14:45:23.890123 openat(AT_FDCWD, "/opt/app/cache.json", O_RDONLY) = 12 <0.523456>
14:45:24.413679 read(12, "{\"key\":\"value\"}"..., 4096) = 4096 <0.000089>

openat с 523ms — ищем причину: файл на NFS, отсутствие прав, удалённый filesystem.

Для SQL-подобных запросов (PostgreSQL, MySQL) трассируем сокет:

# Находим socket fd процесса
ls -la /proc/12345/fd | grep socket
# lr-x 14 -> socket:[1234567]

# Трассируем конкретный fd
strace -p 12345 -e write=14 -f -tt -T

Медленный запрос к БД выглядит как серия write/read с долгим временем между ними:

14:50:01.123 write(14, "SELECT * FROM orders"..., 45) = 45 <0.000234>
14:50:05.890 read(14, "", 4096)          = 2048 <4.766890>

4.7 секунды между отправкой запроса и получением данных — проблема на стороне БД или сети до неё.

Коротко

strace превращает зависание без видимых причин в конкретный syscall. Подключайтесь к PID, фильтруйте вызовы через -e trace=, смотрите время выполнения через -T. Для утечек — сравнивайте open/close в summary mode. Для медленных запросов — ищите вызовы с временем больше 100ms.

Подсказка

На продакшене используйте -e trace=write,read,openat вместо трассировки всех вызовов — снизит overhead в 3–5 раз.