Проблемы трассировки и профилирования ядра мы уже затрагивали в предыдущих публикациях. Для анализа событий на уровне ядра существует много специализированных инструментов: SystemTap, Ktap, Sysdig, LTTNG и другие. Об этих инструментах опубликовано много подробных статей и обучающих материалов.
Гораздо меньше информации можно найти о «родных» механизмах Linux, с помощью которых можно отслеживать системные события, получать и анализировать отладочную информацию. Эту тему мы хотели бы рассмотреть в сегодняшней статье. Особое внимание мы уделим ftrace — первому и пока что единственному инструменту трассировки, добавленному в ядро. Начнём с определения основных понятий.
Профилирование и трассировка ядра
Профилирование ядра — это выявление «узких мест» в производительности. С помощью профилирования можно определить, где именно произошла потеря производительности в той или иной программе. Специальные программы генерируют профиль — сводку событий, на основе которой можно выяснить, на выполнение каких функций ушло больше всего времени. Эти программы, однако, не помогают выявить причину снижения производительности.
«Узкие места» очень часто возникают при определённых условиях, которые при профилировании выявить невозможно. Чтобы понять, почему произошло то или иное событие, требуется восстанавливать контекст. В свою очередь, для восстановления контекста требуется трассировка.
Под трассировкой понимается получение информации о том, что происходит внутри работающей системы. Для этого используются специальные программные инструменты. Они регистрируют все события в системе подобно тому, как магнитофон записывает все звуки окружающей среды.
Программы-трассировщики могут одновременно отслеживать события как на уровне отдельных приложений, так и на уровне операционной системы. Полученная в ходе трассировки информация может оказаться полезной для диагностики и решения многих системных проблем.
Трассировку иногда сравнивают с логгированием. Сходство между этими двумя процедурами действительно есть, но есть и различия.
Во время трассировки записывается информация о событиях, происходящих на низком уровне. Их количество исчисляется сотнями и даже тысячами. В логи же записывается информация о высокоуровневых событиях, которые случаются гораздо реже: например, вход пользователей в систему, ошибки в работе приложений, транзакции в базах данных и другие.
Как и логи, файлы с данными трассировки можно читать «с листа». Гораздо интереснее и полезнее, однако, извлекать из них информацию, которая относится к работе конкретных приложений. Соответствующие функции есть у всех программ-трассировщиков.
В ядре Linux существует три основных механизма, при помощи которых осуществляются процедуры трассировки и профилирования ядра:
- tracepoints — механизм, работающий через статическое инструментирование кода;
- kprobes — механизм динамической трассировки, с помощью которого можно прервать выполнение кода ядра в любом месте, вызвать собственный обработчик и по завершении всех необходимых операций вернуться обратно;
- perf_events — интерфейс доступа к PMU (Performance Monitoring Unit).
Подробно расписывать особенности всех этих механизмов не будем; заинтересованных читателей отсылаем к статье компании «НТЦ МетроТек», а также к блогу Брендана Грегга.
С помощью ftrace можно взаимодействовать с этими механизмами и получать отладочные данные, находясь в пользовательском пространстве. Более подробно об этом мы поговорим ниже. Все примеры команд приводятся для ОС Ubuntu 14.04, ядро версии 3.13.0-24.
Ftrace: общая информация
Название ftrace представляет собой сокращение от Function Trace — трассировка функций. Однако возможности этого инструмента гораздо шире: с его помощью можно отслеживать контекстные переключатели, измерять время обработки прерываний, высчитывать время на активизацию заданий с высоким приоритетом и многое другое.
Ftrace был разработан Стивеном Ростедтом и добавлен в ядро в 2008 году, начиная с версии 2.6.27. Это — фреймворк, предоставляющий отладочный кольцевой буфер для записи данных. Собирают эти данные встроенные в ядро программы-трассировщики.
Работает ftrace на базе файловой системы debugfs, которая в большинстве современных дистрибутивов Linux смонтирована по умолчанию. Чтобы приступить к работе с ftrace, нужно просто перейти в директорию sys/kernel/debug/tracing (она доступна только для root-пользователя):
# cd /sys/kernel/debug/tracing
Подробно рассказывать обо всех содержащихся в ней файлах и поддиректориях мы не будем — это уже сделано в официальной документации. Кратко опишем лишь те из них, которые представляют интерес в контексте нашего рассмотрения:
- available_tracers — доступные программы-трассировщики;
current_tracer — программа-трассировщик, активная в текущий момент; - tracing_on — служебный файл, отвечающий за включение и отключение записи данных в кольцевой буфер (чтобы включить запись, нужно записать в этот файл цифру 1, а чтобы отключить — 0);
- trace — файл, где хранятся данные трассировки в человекочитаемом формате.
Доступные трассировщики
Просмотреть список доступных трассировщиков можно с помощью команды
root@andrei:/sys/kernel/debug/tracing#: cat available_tracers
blk mmiotrace function_graph wakeup_rt wakeup function nop
Приведём краткую характеристику для каждого трассировщика:
- function — трассировщик функций вызовов ядра без возможности получения аргументов;
- function_graph — трассировщик функций вызовов ядра с подвызовами;
- blk — трассировщик вызовов и событий, связанных с вводом-выводом на блочные устройства; именно он используется в утилите blktrace, о которой мы уже писали;
- mmiotrace — трассировщик операций ввода-вывода, отражаемых в память.
- nop — самый простой трассировщик, который, как и следует из названия, ничего не делает (однако в некоторых ситуациях и он может быть полезен, о чём ещё пойдёт речь ниже).
Трассировщик function
Знакомство с ftrace мы начнём с трассировщика function. Рассматривать его мы будем на материале вот такого тестового скрипта:
#!/bin/sh
dir=/sys/kernel/debug/tracing
sysctl kernel.ftrace_enabled=1
echo function > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on
sleep 1
echo 0 > ${dir}/tracing_on
less ${dir}/trace
крипт очень простой и в целом понятный, однако в нём есть моменты, на которые стоит обратить внимание.
Команда sysctl ftrace.enabled=1 включает трассировку функций. Далее мы устанавливаем текущий трассировщик, записывая его имя в файл current_tracer.
После этого мы записываем 1 в файл tracing_on и тем самым активируем обновление кольцевого буфера. Важная особенность синтаксиса: между 1 и знаком > обязательно должен быть пробел: команда вида echo1> tracing_on не сработает. Буквально через одну строку мы его отключаем (обратите внимание: если в файл tracing_on записать 0, кольцевой буфер не будет очищен; не будет отключен и ftrace).
Зачем мы это делаем? Между двумя командами echo находится команда sleep 1. Мы включаем обновление буфера, выполняем эту команду и затем сразу же его отключаем. Благодаря этому в трассировку будет включена информация обо всех системных вызовах, которые имели место во время выполнения этой команды.
В последней строке скрипта мы даём команду вывести данные трассировки на консоль.
В результате выполнения этого скрипта мы увидим следующий вывод (приводим лишь небольшой фрагмент):
# tracer: function
#
# entries-in-buffer/entries-written: 29571/29571 #P:2
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
trace.sh-1295 [000] .... 90.502874: mutex_unlock <-rb_simple_write
trace.sh-1295 [000] .... 90.502875: __fsnotify_parent <-vfs_write
trace.sh-1295 [000] .... 90.502876: fsnotify <-vfs_write
trace.sh-1295 [000] .... 90.502876: __srcu_read_lock <-fsnotify
trace.sh-1295 [000] .... 90.502876: __srcu_read_unlock <-fsnotify
trace.sh-1295 [000] .... 90.502877: __sb_end_write <-vfs_write
trace.sh-1295 [000] .... 90.502877: syscall_trace_leave <-int_check_syscall_exit_work
trace.sh-1295 [000] .... 90.502878: context_tracking_user_exit <-syscall_trace_leave
trace.sh-1295 [000] .... 90.502878: context_tracking_user_enter <-syscall_trace_leave
trace.sh-1295 [000] d... 90.502878: vtime_user_enter <-context_tracking_user_enter
trace.sh-1295 [000] d... 90.502878: _raw_spin_lock <-vtime_user_enter
trace.sh-1295 [000] d... 90.502878: __vtime_account_system <-vtime_user_enter
trace.sh-1295 [000] d... 90.502878: get_vtime_delta <-__vtime_account_system
trace.sh-1295 [000] d... 90.502879: account_system_time <-__vtime_account_system
trace.sh-1295 [000] d... 90.502879: cpuacct_account_field <-account_system_time
trace.sh-1295 [000] d... 90.502879: acct_account_cputime <-account_system_time
trace.sh-1295 [000] d... 90.502879: __acct_update_integrals <-acct_account_cputime
Вывод начинается с информации о количестве записей событий в буфере (entries in buffer) и общем количестве записанных событий (entries written). Разница между этими двумя цифрами — это количество событий, утерянных при заполнении буфера (в нашем случае никаких утерянных событий нет).
Далее идёт перечень функций, включающий следующую информацию:
- идентификатор процесса (PID);
- номер процессорного ядра, на котором выполняется трассировка(СPU#);
- метка времени (TIMESTAMP; указывает время, когда произошёл вход в функцию);
- имя трассируемой функции и имя родительской функции, которая её вызвала(FUNCTION); например, в самой первой строке приведённого нами вывода функцию mutex-unlock вызывает функция rb_simple_write.
Вывод начинается с информации о количестве записей событий в буфере (entries in buffer) и общем количестве записанных событий (entries written). Разница между этими двумя цифрами — это количество событий, утерянных при заполнении буфера (в нашем случае никаких утерянных событий нет).
Далее идёт перечень функций, включающий следующую информацию:
- идентификатор процесса (PID);
- номер процессорного ядра, на котором выполняется трассировка(СPU#);
- метка времени (TIMESTAMP; указывает время, когда произошёл вход в функцию);
- имя трассируемой функции и имя родительской функции, которая её вызвала(FUNCTION); например, в самой первой строке приведённого нами вывода функцию mutex-unlock вызывает функция rb_simple_write.
Трассировщик function_graph
Трассировщик function_graph работает точно так же, как function, но отслеживает функции более подробно: для каждой функции он указывает точку входа и точку выхода. С помощью этого трассировщика можно отслеживать функции с подвызовами и измерять время выполнения для каждой функции.
Отредактируем использованный в предыдущем примере скрипт:
#!/bin/sh
dir=/sys/kernel/debug/tracing
sysctl kernel.ftrace_enabled=1
echo function_graph > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on
sleep 1
echo 0 > ${dir}/tracing_on
less ${dir}/trace
В результате выполнения этого скрипта мы получим следующий вывод:
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) 0.120 us | } /* resched_task */
0) 1.877 us | } /* check_preempt_curr */
0) 4.264 us | } /* ttwu_do_wakeup */
0) + 29.053 us | } /* ttwu_do_activate.constprop.74 */
0) 0.091 us | _raw_spin_unlock();
0) 0.260 us | ttwu_stat();
0) 0.133 us | _raw_spin_unlock_irqrestore();
0) + 37.785 us | } /* try_to_wake_up */
0) + 38.478 us | } /* default_wake_function */
0) + 39.203 us | } /* pollwake */
0) + 40.793 us | } /* __wake_up_common */
0) 0.104 us | _raw_spin_unlock_irqrestore();
0) + 42.920 us | } /* __wake_up_sync_key */
0) + 44.160 us | } /* sock_def_readable */
0) ! 192.850 us | } /* tcp_rcv_established */
0) ! 197.445 us | } /* tcp_v4_do_rcv */
0) 0.113 us | _raw_spin_unlock();
0) ! 205.655 us | } /* tcp_v4_rcv */
0) ! 208.154 us | } /* ip_local_deliver_finish */
В графе DURATION указывается время, затраченное на выполнение функции. Особое внимание следует обратить на пункты, отмеченные значками + и! Знак + означает, что выполнение функции заняло более 10 микросекунд, а восклицательный знак — более 100.
В графе FUNCTION_CALLS с информацией о вызовах функций.
Начало и конец выполнения каждой функции обозначаются в ней так, как это принято в языке C: фигурная скобка в начале функции и ещё одна — в конце. Функции, которые являются листьями графа и не вызывают никаких других функций, обозначаются точкой с запятой (;).
Фильтры для функций
Вывод ftrace порой может быть очень большим, и найти в нём нужную информацию крайне затруднительно. Упростить поиск можно с помощью фильтров: в вывод будет попадать информация не обо всех функциях, а лишь о тех, которые нас действительно интересуют. Для этого достаточно просто записать в файл set_ftrace_filter имена нужных функций, например:
root@andrei:/sys/kernel/debug/tracing# echo kfree > set_ftrace_filter
Чтобы отключить фильтр, нужно записать в этот же файл пустую строку:
root@andrei:/sys/kernel/debug/tracing# echo > set_ftrace_filter
В результате выполнения команды
root@andrei:/sys/kernel/debug/tracing# echo kfree > set_ftrace_notrace
мы получим совершенно противоположный результат: в вывод будет попадать информация обо всех функциях, кроме kfree().
Ещё одна полезная опция — set_ftrace_pid. Она предназначена для трассировки функций, вызываемых во время выполнения указанного процесса.
Возможности фильтрации в ftrace гораздо шире; подробнее о них можно прочитать в статье Стивена Ростедта на LWN.net.
Трассировка событий
Выше мы уже упоминали о механизме tracepoints. Слово tracepoint в переводе означает «точка трассировки». Точка трассировки — это специальная вставка в код, регистрирующая определённые системные события. Точка трассировки могут быть активной (это значит, что за ней закреплена некоторая проверка) или неактивной (никакой проверки за ней не закреплено).
Неактивная точка трассировки никакого влияния на работу системы не оказывает; она лишь добавляет несколько байт для вызова трассировочной функции в конце инструментированной функции, а также добавляет структуру данных в отдельную секцию.
Когда точка трассировки активна, при выполнении соответствующего фрагмента кода вызывается трассировочная функция. Данные трассировки записываются в отладочный кольцевой буфер.
Точки трассировки могут быть вставлены в любое место в коде. Они уже присутствуют в коде многих ядерных функций. Рассмотрим, например, функцию kmem_cache_alloc (взято отсюда):
{
void *ret = slab_alloc(cachep, flags, _RET_IP_);
trace_kmem_cache_alloc(_RET_IP_, ret,
cachep->object_size, cachep->size, flags);
return ret;
}
Обратите внимание на строку trace_kmem_cache_alloc — это как раз и есть точка трассировки. Количество подобных примеров можно умножить, обратившись к исходному коду других функций ядра.
В ядре Linux имеется специальный API, с помощью которого можно работать с точками трассировки из пользовательского пространства. В директории /sys/kernel/debug/tracing есть поддиректория events, в которой хранятся доступные для отслеживания системные события. Системное событие в данном контексте — не что иное, как включенные в ядро точки трассировки.
Их список можно просмотреть с помощью команды:
root@andrei:/sys/kernel/debug/tracing# cat available_events
На консоль будет выведен длинный список, просматривать который довольно неудобно. Вывести этот же список в более структурированном формате можно так:
root@andrei:/sys/kernel/debug/tracing# ls events
Прежде чем приступать к отслеживанию событий, проверим, включена ли запись событий в кольцевой буфер:
root@andrei:/sys/kernel/debug/tracing# cat tracing_on
Если после выполнения этой команды на консоль будет выведена цифра 0, выполним:
root@andrei:/sys/kernel/debug/tracing# echo 1 > tracing_on
В прошлой статье мы писали о системном вызове chroot() — вход в этом системный вызов мы и будем отслеживать. В качестве трассировщика мы выберем nop: function и function_graph записывают слишком много информации, в том числе и не имеющей отношения к интересующему нас событию.
root@andrei:/sys/kernel/debug/tracing# echo nop > current_tracer
Все события, связанные с системными вызовами, хранятся в директории syscalls. В ней, в свою очередь, хранятся директории для входа и выхода из различных системных вызовов. Активируем нужную нам точку трассировки, записав 1 в её enable-файл:
root@andrei:/sys/kernel/debug/tracing# echo 1 > events/syscalls/sys_enter_chroot/enable
Затем создадим изолированную файловую систему с помощью команды chroot (подробности см. в предыдущем посте). После выполнения интересующих нас команд отключим трассировку, чтобы в вывод не попадала информация о лишних и не имеющих отношения к делу событиях:
root@andrei:/sys/kernel/debug/tracing# echo 0 > tracing_on
Далее просмотрим содержимое кольцевого буфера. В самом конце вывода будет содержаться информация об интересующем нас системном вызове (приводим небольшой фрагмент):
root@andrei:/sys/kernel/debug/tracing# сat trace
......
chroot-11321 [000] .... 4606.265208: sys_chroot(filename: 7fff785ae8c2)
chroot-11325 [000] .... 4691.677767: sys_chroot(filename: 7fff242308cc)
bash-11338 [000] .... 4746.971300: sys_chroot(filename: 7fff1efca8cc)
bash-11351 [000] .... 5379.020609: sys_chroot(filename: 7fffbf9918cc)
Более подробно о настройках трассировки событий можно почитать здесь.
Заключение
В этой статье мы проделали общий обзор возможностей ftrace. Будем признательны за любые замечания и дополнения. Если вы хотите глубже погрузиться в тему, рекомендуем ознакомиться со следующими источниками:
- http://ift.tt/1ogiVGJ — подробное описание механизма tracepoints;
- http://ift.tt/1Mvro4o — руководство по трассировке системных событий в Linux;
- http://ift.tt/1kHNAtY — официальная документация ftrace;
- http://ift.tt/1Mvrmt8 — диссертация Матьё Денуайе (создателя механизма tracepoints и автора LTTNG) о трассировке и профилировании ядра;
- http://ift.tt/1QnzlHy — статья Стивена Родстедта о возможностях ftrace;
- http://ift.tt/1ogiVGL — обзорная статья об ftrace c разбором практического кейса;
- http://ift.tt/1Mvrmtc — единственная подробная публикация об ftrace на русском языке.
Если вы по тем или иным причинам не можете оставлять комментарии здесь — приглашаем к нам в блог.
Комментарии (0)