28.03.2016 10:39
AndreiYemelianov 4 6100 Источник
PR-1801-2-2

Проблемы трассировки и профилирования ядра мы уже затрагивали в предыдущих публикациях. Для анализа событий на уровне ядра существует много специализированных инструментов: 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.


Трассировщик 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. Будем признательны за любые замечания и дополнения. Если вы хотите глубже погрузиться в тему, рекомендуем ознакомиться со следующими источниками:


Если вы по тем или иным причинам не можете оставлять комментарии здесь — приглашаем к нам в блог.

Комментарии (4)


  1. OYTIS
    28.03.2016 18:31
    #8826510

    «контекстные переключатели»
    Статья переводная?


    1. AndreiYemelianov
      28.03.2016 18:38
      #8826544

      Нет. Конечно же, "переключения". Спасибо, поправил.


  1. evg_krsk
    28.03.2016 19:27
    #8826626
    +1

    Три абзаца начиная с «Вывод начинается с » задвоились. Пожалуйста, вычитывайте статью перед публикацией.

    Ещё наверное нелишним было бы упомянуть про такую штуку как perf-tools. Как интерфейс к ftrace.

    И спасибо за такой материал на русском и с подробными пояснениями.


  1. weirded
    29.03.2016 13:45
    #8827578
    +3

    Огромное спасибо за статью, вы сделали мою жизнь легче процентов эдак на 70% (пусть и на 2-3 дня в месяц)!