Strace при зависании процесса на сервере и практические фильтры системных вызовов для поиска причины

Служба на сервере зависла: процесс числится в списке задач, но не отвечает, лог молчит, жалобы копятся. Команда ps покажет идентификатор и состояние, top добавит цифры нагрузки, но главный вопрос останется открытым: что процесс делает в эту секунду. Утилита strace отвечает построчно: она перехватывает каждый системный вызов, через который программа обращается к ядру, от открытия файла и чтения сокета до ожидания блокировки и обработки сигнала. По рисунку вызовов зависание превращается в задачу с именем вызова и дескриптором. Ниже собраны рабочие приёмы: подключение к процессу, сводный режим, фильтры по группам и именам, метки времени, типовые картины и ограничители наблюдения.

Подключение strace к работающему процессу и слежение за потомками

У наблюдения два старта: программу запускают под трассой с первой инструкции либо утилиту подключают к уже работающему процессу. Для зависаний основной второй вариант: процесс живёт в памяти со всем состоянием, а перезапуск стирает картину раньше, чем её успевают рассмотреть.

Подключение выполняется ключом -p с идентификатором:

sudo strace -p 1234

Утилита печатает строку о подключении и открывает поток вызовов. Отключение по Ctrl+C не меняет состояние процесса: он продолжает работу, наблюдатель именно отключается, а не завершает службу.

Запуск с самого начала выручает, когда зависание воспроизводится на старте:

strace -f ./app --config /etc/app/app.conf

Ключ -f включает слежение за потомками: fork, vfork и clone создают новые процессы, и каждый попадает в общий поток. Для службы с рабочими процессами режим обязателен, иначе картина ограничится родителем, который спокойно ждёт в wait4, пока вызовы выполняют его дети. В паре с -o ключ -ff раскладывает трассы потомков по отдельным файлам:

strace -f -ff -o /tmp/worker.trace ./app

Для подключения нужны права. Утилита работает через механизм ядра ptrace: root подключается к любому процессу, обычный пользователь ограничен собственной областью и настройками подсистемы yama. Порог задаётся в файле /proc/sys/kernel/yama/ptrace_scope: во многих дистрибутивах по умолчанию разрешена трассировка только собственных потомков, поэтому подключение к чужой службе без sudo заканчивается сообщением Operation not permitted.

Сводный режим со счётчиками вызовов и ошибок для первичной картины

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

sudo strace -c -p 1234

После отключения утилита печатает примерно такую таблицу:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 76.90    8.104000        2019      4012         0 futex
 11.52    1.214000         792      1533      1533 read
  5.80    0.611000         858       712       712 openat
  3.81    0.402000         630       638         0 write
  1.97    0.208000          39      5210         0 clock_gettime
------ ----------- ----------- --------- --------- ----------------
100.00   10.539000                 12105      2245    total

Колонка errors сразу называет проблемные вызовы, счётчик calls показывает интенсивность, seconds распределяет время. В примере читается типичный сюжет: futex с подавляющей долей времени говорит об ожидании блокировки, read с ошибкой на каждом вызове указывает на цикл опроса неблокирующего дескриптора, openat со стопроцентными ошибками ведёт к отсутствующему файлу. Диагноз становится вопросом выбора фильтра.

Для анализа ожиданий полезен ключ -w: он суммирует время по часам, а не по процессорным тратам, и долгие блокировки не прячутся за короткими вычислениями.

Порядок диагностики строится от общего к частному:
1. несколько секунд в режиме -c дают распределение вызовов, времени и ошибок;
2. лидер таблицы подсказывает группу для фильтра, например %network;
3. точечный фильтр по именам сокращает поток до нескольких строк;
4. метки времени и длительность вызовов превращают поток в хронологию;
5. дескриптор из подозрительной строки сверяется с каталогом /proc/PID/fd.

Фильтры по группам системных вызовов и по конкретным именам

Смотреть всё подряд расточительно: поток разбухает до нечитаемости, а класс операций для проверки известен заранее. Ключ -e trace= принимает имена и группы:

sudo strace -e trace=%file -p 1234
sudo strace -e trace=%network -p 1234
sudo strace -e trace=%process -p 1234
sudo strace -e trace=%signal -p 1234
sudo strace -e trace=%memory -p 1234
sudo strace -e trace=%desc -p 1234

Группа %file ловит работу с именами файлов: openat, stat, statx, unlink, rename. Группа %network покрывает сокеты: socket, bind, connect, sendto, recvfrom, accept4. Группа %process описывает жизненный цикл задач: fork, clone, execve, wait4, exit_group. Группа %signal собирает отправку и получение сигналов, %memory отвечает за вызовы отображения памяти вроде mmap и mprotect, %desc покрывает операции над дескрипторами: read, write, close, poll, select.

Точечный фильтр оставляет в трассе только имена из списка:

sudo strace -e trace=openat,connect,futex -p 1234

Обратный ход исключает шум: ожидания futex у многопоточной службы генерируют сотни строк, их вырезают из трассы:

sudo strace -e trace=!futex -p 1234

Аргументы-структуры по умолчанию печатаются сокращённо, ключ -v разворачивает их полностью.

Метки времени, длительность вызовов и вывод в файл для читаемого журнала

Трасса без времени не говорит, когда началось ожидание и как долго оно тянется. Ключи выстраивают хронологию: -t печатает время суток, -tt добавляет микросекунды, -ttt переводит метку в секунды эпохи Unix, -r показывает интервал от предыдущего вызова. Главная метрика для зависаний - ключ -T: он выводит длительность каждого вызова в угловых скобках после результата.

sudo strace -tt -T -p 1234
12:41:03.221435 openat(AT_FDCWD, "/etc/app/app.conf", O_RDONLY|O_CLOEXEC) = 4 <0.000021>
12:41:03.221601 futex(0x7f5b6c0020c8, FUTEX_WAIT_PRIVATE, 0, NULL) = 0 <2.008133>

Строка futex с длительностью две секунды сообщает: поток провёл это время в ожидании блокировки, а не крутился впустую. Так различают ожидание и цикл.

Длинные наблюдения направляют в файл: ключ -o сохраняет трассу целиком, а вместе с -ff каждый процесс получит отдельный журнал:

sudo strace -f -tt -T -o /tmp/app.trace -p 1234

Строки по умолчанию обрезаны на 32 символах. Ключ -s 256 поднимает лимит, имена файлов печатаются целиком всегда, урезание касается только содержимого буферов:

sudo strace -s 256 -p 1234

Дескрипторы по умолчанию отображаются числами, и строка read(4, ...) молчит об источнике. Ключ -y приписывает к числу путь, -yy добавляет сведения о сокетах и устройствах:

sudo strace -y -p 1234

Рабочий рецепт собирает всё вместе: короткий сеанс с выводом в файл и ограничением по времени:

sudo timeout -s INT 15 strace -f -tt -T -s 256 -y -o /tmp/app.trace -p 1234

За пятнадцать секунд файл накопит хронологию с длительностями и путями, сеанс завершится сам.

Типовые картины зависания в трассе от цикла коротких вызовов до блокирующего чтения

Картины зависания повторяются, каждая читается однозначно. Первая - бесконечный цикл коротких вызовов. Трасса забита парами nanosleep и clock_gettime либо чередованием futex с интервалами в микросекунды, ключ -r подтверждает крошечные расстояния между вызовами. Процессор занят полностью, полезной работы нет. Причина обычно в коде или конфигурации: цикл ждёт события, которое никогда не наступит.

Вторая - блокирующее чтение с нулевым результатом. Последняя строка трассы остаётся без возврата: read, recvfrom или readv начался и не завершился. Метка времени показывает, когда ожидание началось, вычитание даёт его длительность. Аргумент называет дескриптор, а каталог процессов источник: файл на диске, сокет или pipe.

Третья - ожидание на незакрывающемся вызове. futex без возврата означает ожидание блокировки, занятой другим потоком: если держатель завис, очередь не рассосётся. poll или epoll_wait без возврата говорит об ожидании события на дескрипторах, wait4 информирует о потомке, который не завершился, accept4 остаётся в ожидании входящих соединений, которых нет. Аргументы вызова почти прямым текстом называют причину.

Четвёртая - повторяющиеся ошибки с одним кодом. Строки вида = -1 ENOENT (нет такого файла или каталога) или = -1 ECONNREFUSED (отказ в соединении) идут подряд десятками:

openat(AT_FDCWD, "/var/lib/app/queue.lock", O_RDWR|O_CREAT) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/var/lib/app/queue.lock", O_RDWR|O_CREAT) = -1 ENOENT (No such file or directory)

Для ядра это рутина, для приложения нередко бесконечные попытки без паузы, которые снаружи выглядят как зависание. Код ошибки задаёт направление поиска: ENOENT ведёт к отсутствующему пути, ECONNREFUSED - к порту, где никто не принимает соединения, EAGAIN - к неблокирующему дескриптору, который читают в цикле без обработки пустого результата.

В многопоточной трассе строки помечаются угловыми скобками unfinished и resumed, когда вывод чередуется между потоками. Вызов, который так и не завершился, остаётся без результата: эта последняя строка чаще всего и есть ответ на вопрос, где стоит процесс.

Анализ цепочек вызовов и поиск дескриптора через каталог процессов

Отдельный вызов говорит немного, смысл собирается из последовательностей. Классическая цепочка работы с файлом: openat возвращает дескриптор, read читает содержимое, close закрывает. Обрыв цепочки информативен не меньше: openat с ошибкой и следующий openat по другому пути выдают порядок поиска конфигурации и файл, который приложение так и не нашло.

Цепочка сетевого клиента: socket готовит дескриптор, setsockopt настраивает параметры, connect устанавливает соединение, sendto отправляет запрос, recvfrom ждёт ответ. Зависание на connect указывает на сеть или удалённую сторону, зависание на recvfrom после успешного соединения - на молчание партнёра.

Дескриптор - связь между строкой трассы и объектом системы. Ключ -y показывает путь прямо в строке, без него помогает каталог процессов:

ls -l /proc/1234/fd
readlink /proc/1234/fd/6

Вывод раскрывает, куда ведёт дескриптор: на файл журнала, на сокет с пометкой socket, на pipe или на стёртый файл с пометкой deleted.

Сопоставление трассы и каталога отвечает на прикладные вопросы: какой файл читается в цикле, какой сокет молчит, какой канал остался без пишущей стороны. read на пустом pipe блокируется, а после закрытия пишущего конца возвращает ноль, и приложение, не готовое к нулевому чтению, превращает это в бесконечный цикл.

Ограничители наблюдения и команды с таймаутом для контроля сеанса

strace - тяжёлый инструмент. Каждый системный вызов наблюдаемого процесса ядро останавливает дважды, на входе и на выходе. Для приложений с десятками тысяч вызовов в секунду замедление заметно, поэтому наблюдение держат коротким: для картины хватает нескольких секунд.

Права - второй ограничитель. Обычному пользователю разрешено подключение к собственным процессам, чужие службы требуют прав root либо привилегии CAP_SYS_PTRACE, а подсистема yama способна ограничить подключение даже к своим процессам. Сообщение Operation not permitted означает не поломку утилиты, а отказ по правилам доступа.

Третий ограничитель - дисциплина отключения: Ctrl+C и сигнал от timeout снимают трассировку, процесс работает дальше, состояние службы не меняется.

Для неостановимого наблюдения сеанс ограничивают утилитой timeout, она завершает strace по истечении заданного времени:

timeout 10 strace -c -p 1234
timeout -s INT 30 strace -f -tt -T -o /tmp/app.trace -p 1234

Первый вариант собирает сводку за десять секунд. Второй имитирует Ctrl+C сигналом INT: тридцать секунд полной трассы уходят в файл, strace отключается сам, процесс продолжает работу. Если ptrace недоступен, подсказку дают файлы ядра: /proc/PID/wchan называет функцию ожидания, /proc/PID/stack показывает стек на стороне ядра.

strace не исправляет зависание и не заменяет отладчик. Его сила в честности: утилита показывает ровно то, что процесс просит у ядра, без домыслов. Несколько секунд сводки, точечный фильтр по имени вызова, метка времени у последней строки - и вместо слова "зависло" в отчёте появляется строка с именем вызова и дескриптором. За строкой стоят конкретные действия: проверить файл, проверить сокет, освободить блокировку или исправить конфигурацию.