Иногда узел ведёт себя как медленный без видимых причин: процессор почти свободен, память есть, а задания выполняются в разы медленнее, чем по расписанию. Подобные вещи редко решаются привычными метриками, потому что проблема сидит не в приложении, а в путешествии его вызовов через ядро. Ftrace, встроенный прямо в ядро Linux, позволяет посмотреть это путешествие поимённо: какие функции ядра вызывались, сколько времени это заняло и что именно тормозит для конкретной задачи. Разберём практическое применение без абстракций: включение точек, фильтрацию, чтение графа вызовов и аккуратную работу на живой машине.
Что видит трассировщик функций в ядре и когда он нужен
Неприятность состоит в одном: чтобы разбирать это путешествие, полезно понимать, как устроен ядерный исполнитель задачи, и тема поначалу выглядит как закрытая дверь. Перед тем как включать инструменты, полезно понять, что именно они показывают. Пользовательское пространство обращается к ядру через системные вызовы, но механика под капотом состоит из цепочки функций: чтение из сокета вряд ли это функциональный приём, а скорее дорога через чтение из файловой системы, проверку полномочий, локировки, обращение к драйверу и обратно. И вот инструмент strace покрывает эту дорогу на стороне процесса, а ftrace позволяет остаться внутри ядра и показать конкретные функции с временем.
Трассировка такого рода имеет смысл, когда вопрос стоит не "что делает процесс", а "почему ядро так долго его обслуживает". Тормознутое выключение виртуальной машины, задержки на запись на блочное устройство, задержки при выделении памяти - все эти вещи на уровне вызовов выглядят как длинные функции, и там же концентрируется ответ. Для иной категории вопросов, вроде того, какой процесс читает какой файл, лучше служат точки событий, потому что они дают агрегированные данные без хождения по вызовам.
Точка входа в этот мир согласно документации сидит в каталоге отладочной файловой системы, который не заполняется руками: сначала она монтируется, и дальше текущая конфигурация читается и пишется прямо в файлы, как будто бы они настоящие. Всё управление происходит суперпользователем через чтение и запись файлов, и это важно для регулярной работы. Такая форма управления выглядит непривычно по меркам администрирования, но стоит ей привыкнуть один раз, и она оказывается лучшей документацией возможностей ядра, чем сама документация.
Включение трассировщика и первый поток вызовов
Начальный ритуал такой: кидаем запрос монтирования файловой системы, смотрим, какие трассировщики доступны на запущенном ядре, и включаем нужный:
mount -t tracefs nodev /sys/kernel/tracing 2>/dev/null || \
mount -t debugfs none /sys/kernel/debug
cd /sys/kernel/tracing 2>/dev/null || cd /sys/kernel/debug/tracing
cat available_tracers
echo function > current_tracer
echo > trace
echo 1 > tracing_on
sleep 2
echo 0 > tracing_on
head traceВключение выполняется через запись строки в файл конфигурации, и та же машина продолжает работать параллельно только с небольшим замедлением. Два момента здесь утомительны в хорошем смысле. Первый это сброс: записать пустую строку в файл trace перед запуском, иначе в буфере останутся события прошлых прогонов. Второй это объём: буфер трассировки ограничен размером на процессор, и при слишком долгой работе старые события вытесняются новыми, поэтому короткие окна события честнее, чем непрерывные наблюдения.
Фильтрация по функциям и по задачам
Трассировка вешается по функциям файлами фильтров, и именно они делают её пригодной практически: перечислять в set_ftrace_filter нужные имена функций через пробел, а в set_ftrace_notrace записывать исключения, сужает картину до нужного, иначе поток забивается тысячами вызовов в глубинах обычных драйверов. Для задач делают то же самое через фильтрацию pid, и пример работы выглядит типично:
cd /sys/kernel/tracing
echo "schedule" > set_ftrace_filter
echo > set_ftrace_notrace
echo "kfree" >> set_ftrace_filter
echo 1 > tracing_on; sleep 1; echo 0 > tracing_on
head -20 traceАналогичная идея применяется и к наблюдению за конкретным процессом: файл set_ftrace_pid принимает идентификатор, и трассировка печатает вызовы функций только для него. Именно такой путь снимает главное опасение перед трассировкой на сервере, потому что внимание остаётся приковано к целевому процессу, а ядро вокруг показывает только его шаги.
Здесь пригождается одна практика из серии "сгорел, пока не понял": фильтр по нечётким именам подходит, когда ядро включает в себя много вариантов одного вызова через точки с запятой, поэтому перед применением фильтра полезно смотреть вывод доступных функций через cat available_filter_functions. Писать фильтры хорошо точными именами из этого списка, потому что их отсутствие в списке приводит не к записям по ошибке, а к пустому следу.
Граф вызовов и поиск длинных операций
Для медленных операций интереснее граф вызовов: он показывает, какая функция стартовала другую и какое время они в сумме потратили. Трассировщик function_graph печатает вложенность заведёнными табуляциями, а задержка работы указывается прямо в строке символом длительного интервала. Запуск делается так же через файл конфигурации, только теперь идея "что вызвало что" сама по себе смотрится читабельнее любого журнала.
cd /sys/kernel/tracing
echo function_graph > current_tracer
echo 1 > tracing_on
sleep 1
echo 0 > tracing_on
head -40 traceОтвет на вопрос "что так долго" виден как вложенный вызов с заметно большим временем: визуально это тяжёлая ветвь в лесу обычных графов. Когда задача ограничена одним событием, записи повторяются одними и теми же именами, и проблемная функция сразу светится своей длительностью. В этом и прочность схемы: никаких внешних сборок, достаточно каталога и нескольких команд в терминале.
Фронтенд trace cmd и настройка событий
Напрямую файлы манипулируются, но для практики удобнее trace cmd: утилита упаковывает вызовы и повторяет одни и те же операции через прямые файлы ядра. Запись событий с ограниченным набором выглядит кратче и отчётливее:
trace-cmd record -p function -l do_sys_open sleep 1
trace-cmd report | head -30Преимущество в том, что работа с повторяющимся набором фильтров уже оформлена шаблоном: необходимость редактировать каталоги трассировки через прямой доступ к файлам практически исчезает. Команда читается непосредственно и логично: собрать события по function_tracer, записать, прочитать. Для рутинных сеансов подобного рода хватает двух-трёх команд вместо серии запросов к виртуальным файлам.
Типовые приёмы для медленных операций
Готовая коллекция приёмов повторяется из задачи в задачу, и полезно вести их рядом:
- группировать события по имени функции через небольшой скрипт на awk или python, чтобы увидеть распределение задержек;
- перед сбором чистить трассировочный буфер, чтобы случайные события прошлых запусков не путали картину;
- записывать вместе с трассировкой нагрузку системы сиюсекундно, чтобы понять, была ли система занята внешним фактором;
- на боевой среде применять ограниченные окна в пару секунд и перепроверять первые результаты на сервере с иной нагрузкой, потому что замедление быстро меняет порядок вызовов.
Такие приёмы звучат как перестраховка, но именно они трансформируют трассировку из любопытства в управляемый процесс, который можно запускать на продакшен без неожиданностей.
Трассировка функций помогает понять, сколько времени занимает вызов, а точки событий конкретизируют сам факт: когда перешли к процессу, сколько было заблокированных операций, какие события с файловой системой происходили. Настройка работает через файлы в каталоге events: устанавливаются разрешённые события, и трассировка заводится по факту события. Многие при этом идут от практического: задержки чтения или записи удобно смотреть через события блочного подсистемы, а вопросы планировщика вскрываются событиями пробуждения процессов.
Пример благородной проверки на замедления доступа к данным выглядит так: включить события block, дать секунд десять активной работы и остановить. В выводе читается, когда конкретная очередь диска была занята и какое устройство её держало. Такая картина намного совершеннее гипотез о плохом диске, потому что показывает именно те записи, которые применялись в момент замедления, и задержка видна не в средних по дню, а в череде запросов.
Для длительных походов в трассировке нужен не поток, а порог: настройка максимальной задержки фиксирует только функции, которые жили дольше установленного порога, и журнал остаётся коротким. Такая форма работы подходит не для пояснительных докладов, а для наблюдения за редкими всплесками, когда иногда случается пауза, превышающая секунды, и нужен стек того, что именно её делало. Файлы управления для этого присутствуют и в старых, и в новых ядрах, а вывод в статистике показывает длиннейшие вызовы с датами.
Там, где нужно сохранить непрерывную проводку, помогает чтение прямого потока: файл trace_pipe транслирует события по мере их появления, и программное чтение в реальном времени пишет события на диск быстрее, чем они вытесняют старые из буфера. Упорядоченность здесь решает всё: читающий темп не отставать от записывающего.
Для разборов человеком и машиной осваивается режим отчётов вместо сырого вывода, потому что распределение событий по функциям и по длительности прочитывается вместо ручного чтения. Наибольшая дисциплина тут совпадает с метриками: если хотя бы раз встать перед необходимостью ругаться не по абстрактной загруженности, а по конкретной функции, желание читать длинный поток событий распандоривается, и инструмент обыкновенно вшивается в привычки. Иначе и быть не может, когда один вечер трассировки объясняет привычки ядра лучше, чем месяц чтения форумов и перечитывания заметок. Опытной привычкой становится не чтение всего подряд, а их агрегированная сводка, которую дают инструменты вроде trace cmd или короткая обработка выводов в awk и sort.
Длительное наблюдение и стоимость трассировки на живой машине
Плата за видимость непомерна зрению: трассировка функций это задержка на каждый вызов, и на многажды активном сервере время её приходится считать. Поэтому практичный этикет построен на коротких надрагиваниях. Обыденная ошибка про сисадмина знакома почти всем серьёзным историям о наблюдении: трассировка записывается в кольцевой буфер, и если смотреть только последнюю партию файла, легко упустить самую медленную часть, записанную в самом начале. С этой целью продвинутые читатели настраивают и объём буфера заранее с надеждой на отслеживание длиннейших вызовов, а не на финальную секунду перед остановкой. Первый проход это пара секунд активного окна: запись останавливается, буфер читается, смотрим, что светится. Если нужна более конкретная картина, добавляем фильтры и таймеры туда, где уже ясно видно желаемое. Замечательно, что даже с этими ограничениями трассировка выдаёт обрывки ответа, которых не даёт ни один другой бесплатный способ наблюдать медленности ядра. Если нужно продолжительное наблюдение, то уже смотрят на точки событий и метрики, а не на каждый вызов: такие счётчики работают сутками без агрессивной записи в буфер.
Отдельная важная история это узнавание ограничений самой схемы. Записи событий трассировки держатся в кольцевом буфере, и при переполнении старые события теряются. Доказательством этому служат типичные сообщения о потере событий, поэтому при необходимости длительной записи буфер вручную повышается файлом настроек, а окончание трассировки проталкивается явной командой остановки. На производственном сервере подобный порядок выглядит профессиональнее, чем когда всё бросается вместе. Такие записи сохраняют как образцы работы под нагрузкой, и зрелые команды складывают их рядом с описанием инцидента, потому что разбор минувшей аномалии по живому следу намного полнее любого пересказа по памяти.