strace — ваш рентген для любой программы

strace — утилита, без которой невозможно представить серьёзную работу с Linux. Она перехватывает каждый syscall программы и показывает: что вызвано, с какими аргументами, что вернулось, сколько времени заняло. Когда вы не знаете, что делает чужая программа, или почему ваша падает с непонятной ошибкой, или где тормозит — strace даёт ответ за минуту.

В этом уроке: как читать вывод strace, как пользоваться фильтрами, и три реальных кейса диагностики, на которых вы поймёте, почему опытные SRE стартуют со strace, не с reading documentation.

Зачем учиться читать strace

strace решает целый класс задач:

«Программа падает с тихой ошибкой». strace покажет последний syscall перед смертью — обычно сразу видна причина.
«Где открывается этот конфиг?» strace покажет все openat() — видны все пути, по которым программа ищет файлы.
«Почему долго стартует?» strace -c покажет распределение времени по syscall.
«Куда лезет программа?» strace покажет все сетевые connect(), все обращения к файлам, все fork()/exec().
«Что вообще делает этот binary?» strace — быстрейший способ понять, не читая код.

И главное: strace — это страховка против magic-объяснений. «Программа не работает — проблема с правами/сетью/конфигом». strace покажет точный syscall и точную ошибку. Не нужно гадать.

Базовое использование

# Простейший вариант -- запустить программу под strace:
strace ls /etc 2>&1 | head -20

# Сохранить в файл (вывод strace идёт в stderr):
strace -o /tmp/trace.log ls /etc

# Прицепиться к работающему процессу:
strace -p 12345
# Прервать через Ctrl-C -- процесс продолжит работать

Вывод выглядит так:

openat(AT_FDCWD, "/etc", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
getdents64(3, /* 142 entries */, 32768)  = 4848
getdents64(3, /* 0 entries */, 32768)    = 0
close(3)                                 = 0
write(1, "ssh\npasswd\nhosts\n...\n", 89)  = 89

Формат каждой строки:

Имя syscall — openat, fstat, и т.д.
Аргументы в скобках — что передано. Указатели разыменованы, структуры в человекочитаемом виде, массивы тоже.
= и возвращаемое значение — результат. -1 = ошибка, с описанием errno справа.

Как работает strace -- ptrace перехватывает каждый syscall

Target process

syscall

ptrace stop

strace reads regs

format

Human readable output

Из-за того что каждый syscall останавливает процесс, strace замедляет работу в 2-10 раз. На production это терпимо для коротких диагностических сессий.

Фильтры: -e trace

Без фильтра strace заваливает вывод. Самое важное — -e trace=...:

# Только определённые syscall:
strace -e trace=openat ls /etc
strace -e trace=read,write,close cat /etc/hostname
strace -e trace=network curl https://example.com    # все сетевые
strace -e trace=file ls /etc                         # все file-related
strace -e trace=process ps                           # fork, exec, wait, kill
strace -e trace=memory python3 -c ""                 # mmap, munmap, brk
strace -e trace=signal python3 ...                   # signal-related
strace -e trace=ipc ...                              # SysV IPC

Множества можно комбинировать:

# Network + file:
strace -e trace=network,file curl https://example.com 2>&1 | head -30

# Исключить (с !):
strace -e trace=\!brk,mmap,munmap python3 -c "" 2>&1 | head -20
# Memory-аллокации не показывать (их обычно много, шум)

-c — статистика

-c (count) даёт сводную статистику вместо построчного вывода:

strace -c python3 -c "import json; json.dumps({'a':1})" 2>&1 | tail -25

Пример вывода:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 18.45    0.000125           1       125           rt_sigaction
 15.20    0.000103           2        52           mmap
 12.40    0.000084           1        67           openat
 11.80    0.000080           2        38           read
  ...
------ ----------- ----------- --------- --------- ----------------
100.00    0.000677                     447         5 total

Колонки:

% time — доля времени, потраченная на этот syscall.
seconds — абсолютное время.
usecs/call — среднее на один вызов.
calls — количество вызовов.
errors — сколько вернули ошибку.
syscall — имя.

Это бесценно для профилирования. «Где тормозит наша программа?» — strace -c за минуту покажет.

# Сравнить два варианта реализации:
strace -c -e trace=read,write python3 buffered.py 2>&1 | tail -10
strace -c -e trace=read,write python3 unbuffered.py 2>&1 | tail -10
# Увидите: 'buffered' -- 10 write syscall. 'unbuffered' -- 10000. Discovery!

-f — следовать за форками

По умолчанию strace следит только за основным процессом. -f (follow forks) расширяет это на все потомков:

# Без -f -- увидите fork(), но не то, что делает потомок:
strace bash -c 'ls /etc | head'

# С -f -- увидите оба процесса:
strace -f bash -c 'ls /etc | head' 2>&1 | head -20
# В выводе будут [pid 1234] и [pid 1235] -- разные процессы.

Это критично для shell-скриптов, Python с subprocess, любых программ, которые fork’аются. Без -f вы видите только половину картины.

-p — attach к работающему процессу

Невероятно полезный режим. Можно прицепиться к долгоживущему сервису и посмотреть, что он делает прямо сейчас:

# Узнать PID сервиса:
pgrep -f my-app
# 12345

# Прицепиться:
sudo strace -p 12345

# Лучше с -e фильтром, чтобы не задушиться шумом:
sudo strace -p 12345 -e trace=read,write,connect

# Можно следить за всеми тредами:
sudo strace -p 12345 -f

Ctrl-C отключит strace, процесс продолжит работать без него. Это безопасно для production (с оговоркой — strace замедляет процесс в ~2-10 раз из-за overhead перехвата каждого syscall).

# Прицепиться ко всем тредам приложения и подсчитать syscall за 10 секунд:
sudo strace -c -f -p $(pgrep -f my-app) -- sleep 10

-y — показывать имена FD

По умолчанию strace показывает FD числом: read(7, ...). Это бесполезно, если у вас 30 открытых FD. -y добавляет имена:

strace -y -e trace=read,write,openat cat /etc/hostname
# openat(AT_FDCWD, "/etc/hostname", ...) = 3</etc/hostname>
# read(3</etc/hostname>, "myhost\n"..., 131072) = 7
# write(1</dev/pts/0>, "myhost\n", 7) = 7
# close(3</etc/hostname>) = 0

Сразу видно: 3 — это /etc/hostname, 1 — терминал. Намного читаемее.

-t -T -tt — время

-t — timestamp каждого syscall (час:минута:секунда).
-tt — с микросекундами.
-T — сколько потратил каждый syscall.
-ttt — timestamp в формате Unix time.

strace -tt -T cat /etc/hostname
# 12:34:56.123456 openat(AT_FDCWD, "/etc/hostname", O_RDONLY|O_CLOEXEC) = 3 <0.000023>
# 12:34:56.123512 fstat(3, {st_mode=S_IFREG|0644, st_size=7, ...}) = 0 <0.000012>
# ...
# <0.000023> -- syscall занял 23 микросекунды.

Это бесценно для понимания, где медленно. Видите syscall longer than 1 секунду — проблема найдена.

Типичный workflow диагностики через strace

Проблема

strace -e trace=...

Grep errors / slow

Find culprit syscall

Fix

Реальный кейс 1: «программа падает с тихой ошибкой»

$ ./mybinary
$ echo $?
1
# Что произошло??

$ strace -e trace=open,openat,access ./mybinary 2>&1 | tail -10
# ...
# openat(AT_FDCWD, "/usr/local/share/mybinary/config.json", O_RDONLY) = -1 ENOENT (No such file or directory)
# +++ exited with 1 +++

# Аха! Программа ищет конфиг в /usr/local/share/mybinary/, его нет.

Без strace вы бы гадали часами. С strace — 30 секунд, и причина найдена.

Реальный кейс 2: «бэкенд тупит на одном запросе»

Web-сервис стал отвечать в 10 раз медленнее. Из логов непонятно, что происходит. Прицепляемся:

sudo strace -tt -T -f -p $(pgrep -f myapp) -e trace=read,write,connect 2>&1 | tee /tmp/trace.log

# Через 30 секунд Ctrl-C, смотрим:
grep -E '\<[1-9][0-9]\>' /tmp/trace.log | head
# Ищем syscalls с временем >10 секунд
# 12:34:56 connect(15, ...) <12.345678>
# Сервис висит на connect к чему-то 12 секунд!

# Что это за адрес:
grep 'connect.*= 15' /tmp/trace.log
# connect(15, {sa_family=AF_INET, sin_port=htons(5432), sin_addr=inet_addr("10.0.0.5")}, 16)
# Подключение к Postgres на 10.0.0.5:5432 висит 12 секунд

# Проверяем сеть:
ping -c 3 10.0.0.5
# 0 packets received, 100% packet loss
# Аха! Postgres недоступен по сети, connect timeout, отсюда замедление.

Реальный кейс 3: «странная permission denied»

$ ./writer
Error: cannot write to log
$ ls -l /var/log/myapp/
drwxrwxr-x 2 myapp myapp 4096 May 18 12:00 /var/log/myapp/
# Права 775, я в группе myapp -- должно работать?

$ strace -e trace=openat,open ./writer 2>&1 | grep -i denied
# openat(AT_FDCWD, "/var/log/myapp/app.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = -1 EACCES (Permission denied)

$ ls -l /var/log/myapp/app.log
-rw-rw-r-- 1 root root 1234 May 18 11:00 /var/log/myapp/app.log
# Файл существует, владелец root, не myapp! Это и есть проблема.

# Решение:
sudo chown myapp:myapp /var/log/myapp/app.log
# Теперь работает.

strace показал точный путь и точный syscall с EACCES — сразу видно, что проблема не с директорией, а с конкретным файлом.

Полезные опции

# Показывать только syscall, вернувшие ошибку:
strace -Z program
# Полезно для дебага -- сразу видны все провалившиеся вызовы

# Длинные строки не обрезать (default -- ~32 символов):
strace -s 1024 program

# Включить раздачу аргументов структур (verbose):
strace -v program

# Показывать только PID без других данных:
strace --output-separately -o trace -f program
# Создаст отдельные файлы trace.PID для каждого процесса

# Print syscall на input/output данные:
strace -e read=3 program       # дам hex dump того, что прочитали через FD 3
strace -e write=1 program      # дамп того, что пишется в stdout

strace -k — stack traces (если есть)

С -k strace показывает stack trace для каждого syscall (требует libunwind или libbfd):

strace -k -e trace=write ./myapp 2>&1 | head -20
# write(1, "hello\n", 6) = 6
# > /lib/x86_64-linux-gnu/libc.so.6(write+0x14) [0x...]
# > /usr/bin/myapp(main+0x42) [0x...]
# > /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xea) [0x...]

Бесценно для C-программ, где надо понять, откуда вызывается syscall. Для Python менее полезно (видно только Python interpreter).

Альтернативы и расширения

ltrace — то же, но для library calls (libc, etc), не для syscall. Видно strlen, malloc, printf вместо syscall.
perf trace — современная альтернатива strace, меньше overhead, использует ftrace внутри.
bpftrace — мощнее, скриптуется. bpftrace -e 'tracepoint:syscalls:sys_enter_openat /pid == 1234/ {printf("%s\n", str(args->filename))}'
eBPF/bcc — огромный набор инструментов: opensnoop, execsnoop, tcpsnoop, и т.п. Низкий overhead, можно использовать в production.

Для глубокого профилирования perf и bpftrace лучше — меньше overhead и больше возможностей. Но для быстрой диагностики простота strace непобедима.

ps и /proc: найти PID для strace -p

Попробуй сам

# 1. Что делает простая команда -- очень обзорно:
strace -c ls / 2>&1 | tail -15

# 2. Где открывается /etc/hosts:
strace -e trace=openat curl https://example.com 2>&1 | grep -i hosts

# 3. Что включает в себя 'date':
strace date 2>&1 | head

# 4. Куда подключается curl:
strace -e trace=connect,sendto curl https://example.com 2>&1 | head -10

# 5. Прицепиться к shell и посмотреть, что делает:
sudo strace -p $$ -e trace=read
# В другом терминале нажимайте на клавиши -- увидите read из stdin

# 6. Сравнить производительность -- два способа чтения файла:
echo "test data" > /tmp/test.txt
strace -c python3 -c "
with open('/tmp/test.txt') as f:
    for line in f: pass
" 2>&1 | tail -10

strace -c python3 -c "
import os
fd = os.open('/tmp/test.txt', os.O_RDONLY)
while os.read(fd, 1): pass
os.close(fd)
" 2>&1 | tail -10
# Сравните количество read syscall

# 7. Узнать, почему ваш скрипт падает:
strace -e trace=open,openat,access,stat ./broken_script.sh 2>&1 | grep -i 'ENOENT\|EACCES\|denied'

# 8. Чёткое профилирование Python:
strace -c -f python3 your_app.py 2>&1 | tail -30
# Топ syscalls по времени -- ваше bottleneck

# 9. Сетевая активность Python-приложения:
strace -e trace=network -p $(pgrep -f your-app) -f 2>&1 | head -50

Проверка знанийKnowledge check

Python-сервис стал медленно отвечать на запросы (раньше 50ms, теперь 5 секунд). Top показывает нормальный CPU, ничего экстремального. Логи не показывают ошибок. Как с помощью strace найти причину за 5 минут?

ОтветAnswer

План диагностики через strace: 1) Найти PID процесса: ``` pgrep -f my-service # 12345 ``` 2) Прицепиться с timing и follow-forks (важно: -tt -T): ``` sudo strace -tt -T -f -p 12345 -e trace=read,write,connect,recv,send,recvfrom,sendto,poll,epoll_wait 2>&1 | tee /tmp/svc.log ``` Параллельно запустить медленный запрос. Через 30 секунд Ctrl-C. 3) Искать долгие syscall в логе: ``` grep -E '<[1-9]\.|<[1-9][0-9]\.' /tmp/svc.log ``` Это regex для syscall, занявших >1 секунды. Получаем строки вроде: ``` connect(15, sockaddr_in("10.0.0.5":5432), 16) <4.234567> read(15, "...", 4096) <0.892341> ``` 4) Анализ: - Если `connect` висит 4 секунды -- проблема с сетью, DNS, или TCP до этого endpoint. Проверить ping/nc. - Если `read` с socket FD висит секунды -- удалённый сервис (БД, кеш, API) медленно отвечает. - Если `read` с файлового FD висит -- диск тормозит, проверить iostat. - Если `poll/epoll_wait` -- сервис ждёт ввода, может быть, недостаточно workers для нагрузки. - Если `futex` висит -- блокировка между threads, look for deadlock or contention. 5) Расширить диагностику: `strace -y` показал имена файлов и сокетов -- проще понять, что это за FD 15. Если это `socket:[12345]` -- можно посмотреть в /proc/PID/net/tcp: ``` grep -i $(printf '%X' 12345) /proc/12345/net/tcp ``` Покажет remote IP:port -- куда подключаемся. 6) Альтернативные источники: - `ss -tnp | grep 12345` -- TCP connections процесса. - `lsof -p 12345` -- все открытые FDs. - `/proc/12345/status` -- общая инфа. - `/proc/12345/stack` -- где в kernel застрял (если sleeping в syscall). Типичные находки в реальной практике: - DNS lookup на каждый запрос. `gethostbyname` -> `socket+connect+recv` к /etc/resolv.conf'у. Решение: кешировать или использовать persistent connections. - Тyпит подключение к БД. Сетевая проблема или perf проблема Postgres. strace показывает, что connect или query медленные. - Slow disk I/O. Например, лог-файл на медленном NFS-mount, и write блокирует основной поток. - Lock contention. Сотни процессов futex на одном объекте. Преимущество strace -- не нужно правок кода, не нужно перезапуска сервиса, не нужно специальных инструментов. За 5 минут точно знаете, чем занят процесс.