Трассировщик функций ftrace

image_print

Трассировщик функций ftrace

PDF

Ftrace — это внутренний трассировщик ядра, позволяющий разработчикам посмотреть, что происходит внутри ядра системы. Трассировщик можно использовать для отладки, анализа задержек или или производительности, связанных с операциями за пределами пользовательского пространства.

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

Одним из наиболее распространенных применений ftrace является отслеживание событий. В ядре имется сотни статических событий, которые могут быть включены через файловую систему tracefs для просмотра происходящего в отдельных частях ядра.

Дополнительную информацию о событиях можно найти в файле events.txt
документации ядра.

Детали реализации трассировщика описаны в файле ftrace-design.

Оглавление

Исключено в версии HTML

Файловая система

Ftrace использует файловую систему tracefs для хранения управляющих файлов и данных.

При настройке tracefs в ядре (выбор любой из опций ftrace) создается каталог /sys/kernel/tracing. Для автоматического монтирования этого каталога можно добавить в файл /etc/fstab команду

tracefs	/sys/kernel/tracing	tracefs defaults	0	0

Можно монтировать файловую систему по мере надобности с помощью команды

mount -t tracefs nodev /sys/kernel/tracing

Для быстрого доступа к каталогу можно создать символьную ссылку

ln -s /sys/kernel/tracing /tracing

Примечание. До версии ядра 4.1 управление трассировкой происходило в рамках файловой системы debugfs, обычно называемой /sys/kernel/debug/tracing. Для совместимости с прежними версиями при монтировании файловой системы debugfs автоматически монтируется система tracefs как /sys/kernel/debug/tracing1.

Все файлы системы tracefs доступны и в файловой системе debugfs.

Все выбранные опции ftrace будут отражаться и в файловой системе tracefs. Далее в документе предполагается текущим каталог ftrace (cd /sys/kernel/tracing) и файлы будут именоваться относительно этого каталога без указания полного пути /sys/kernel/tracing.

Исходя из того, что настройка ftrace в ядре присутствует, после монтирования tracefs вы получите доступ к управлению и выходным файлам ftrace. Ниже описаны некоторые из этих файлов.

current_tracer

Указывает текущий настроенный трассировщик.

available_tracers

Содержит список трассировщиков, включенных в ядре. Эти трассировщики можно настраивать, помещая имя нужного трассировщика с помощью команды echo в файл current_tracer.

tracing_on

Устанавливает или показывает состояние записи в кольцевой буфер трассировки. Запись 0 в этот файл отключает запись, 1 включает. Отметим, что это влияет лишь на запись в кольцевой буфер, а связанные с трассировкой издержки могут сохраняться.

Функция ядра tracing_off() может применяться внутри ядра для отключения записи в кольцевой буфер, помещая 0 в указанный файл. Можно восстановить запись из пользовательского пространства, отправив в файл значение 1.

Отметим, что функция и триггер событий traceoff также будут помещать в файл значение 0 и останавливать запись. Для восстановления записи служит указанный выше способ записи значения 1 в файл.

trace

В этот файл записывается вывод трассировки в понятном человеку формате (см. ниже). Отметим, что трассировка приостанавливается при чтении этого файла (open).

trace_pipe

Вывод в этот файл такой же как в trace, но файл предназначен для потоковой трассировки. Чтение из файла блокируется на время записи новых данных. В отличие от trace, этот файл является «потребителем» — считывание из этого файла «потребляет» данные и они уже не будут видны при последующих обращениях. Файл trace является «статическим» и если трассировщик не добавляет в него данных, при каждом обращении будет считываться одна и та же информация. При считывании файла trace_pipe трассировка не отключается.

trace_options

Этот файл позволяет пользователю контролировать объем данных, отображаемых в одном из указанных выше выходных файлов. Имеются также опции для изменения режима работы трассировщика и событий (трассировка стека, временные метки и . п.).

options

В этом каталоге расположены файлы для каждой доступной опции трассировки (те же, что в trace_options). Опции могут быть включены и отключены записью 1 или 0 (соответственно) в файл с именем опции.

tracing_max_latency

Некоторые из трассировщиков записывают максимальные задержки, например, максимальную продолжительность запрета прерываний. Данный файл служит для записи такой информации. Значение в файле меняется лишь в том случае, когда измеренная задержка превышает записанную ранее, т. е. значение в файле никогда не уменьшается, пока не будет сброшено. Задержка (и другие временные параметры, упоминаемые далее) указывается в микросекундах. Значение максимальной задержки сохраняется также в файле trace.

tracing_thresh

Некоторые трассировщики задержки записывают значение в файл, если оно превышает величину, указанную в этом файле (порог). Опция активна лишь при указании в файле значения больше 0 (в микросекундах).

buffer_size_kb

Размер буфера для каждого CPU в килобайтах. По умолчанию буферы трассировки имеют одинаковый размер для всех процессоров. Буферы трассировки выделяются страницами (блоками памяти, используемыми ядром; размер страницы обычно составляет 4 килобайта). Если последняя выделенная страница имеет размер больше запрошенного, реальный буфер будет использовать все пространство, а не то, которое запрошено и отображается. Отметим, что размер буферов не обязан быть кратным размеру страницы из-за метаданных управления буферами.

Размеры буферов для отдельных CPU могут различаться (см. per_cpu/cpu0/buffer_size_kb ниже) и в этом случае файл будет содержать значение X.

buffer_total_size_kb

Общий размер буферов трассировки в килобайтах.

free_buffer

Если процесс выполняет трассировку и кольцевой буфер нужно «освободить» после завершения процесса, даже если процесс уничтожен по сигналу, лоя освобождения буфера можно использовать этот файл. При закрытии данного файла размер кольцевого буфера снижается до минимального. Выполняющий трассировку процесс открывает этот файл и при завершении процесса дескриптор файла будет освобождаться. В результате файл будет закрыт и кольцевой буфер «освободится».

При установке опции disable_on_free трассировка будет останавливаться.

tracing_cpumask

Маска, позволяющая пользователю задать трассировку лишь для нужных CPU. Маска указывается в шестнадцатеричном формате.

set_ftrace_filter

При динамической трассировке (см. dynamic ftrace ниже) код динамически изменяется для запрета вызова профилировщика функций (mcount). Это позволяет выполнить трассировку практически без влияния на производительность. Однако имеется побочное влияние на включение или отключение трассировки определенных функций. Отправка (echo) имен функций в этот файл ограничивает трассировку лишь включенными в список функциями. Это влияет на трассировщики function и function_graph, а также на профилировку функций (см. function_profile_enabled).

Функции, перечисленные в файле available_filter_functions могут быть записаны в файл фильтров.

Этот интерфейс можно использовать также для команд (см. Команды фильтрации).

set_ftrace_notrace

Это антипод set_ftrace_filter и любая функция, добавленная в файл, не будет трассироваться. При указании функции в set_ftrace_filter и set_ftrace_notrace трассировка этой функции выполняться не будет.

set_ftrace_pid

Указывает трассировщику function отслеживать лишь функции с PID, указанным в этом файле.

Если установлена опция function-fork, при ветвлении задачи с указанным в этом файле PID, значения PID дочерних процессов будут автоматически добавляться в этот файл и дочерние процессы также будут отслеживаться. При завершении задачи PID удаляется из файла.

set_event_pid

Задает
трассировку событий лишь для процессов,
PID указан
в этом файле
.

Отметим,
что
sched_switch и sched_wake_up также будут отслеживать события, указанные в этом файле.

Для добавления в файл PID дочерних процессо при ветвлении следует включить опцию event-fork (по завершении процесса PID будет удаляться из файла).

set_graph_function

Функции, указанные в этом файле и вызванные ими функции, будут отслеживаться трассировщиком function_ graph (см. Динамическая трассировка ftrace). Отметим, что set_ftrace_filter и set_ftrace_notrace сохраняют влияние на набор отслеживаемых функций.

set_graph_notrace

Похожа на set_graph_function, но отключает трассировщик function_graph до выхода из указанной в этом файле функции. Это позволяет пропустить трассировку функций, вызываемых из заданной функции.

available_filter_functions

Этот файл содержит список функций, для которых возможна трассировка, указанных по именам. Эти функции можно передать в опции (файлы) set_ftrace_filter, set_ftrace_notrace, set_graph_function и set_graph_notrace для управления их трассировкой (см. Динамическая трассировка ftrace)

dyn_ftrace_total_info

Этот файл служит для отладки и указывает число функций, которые были преобразованы в nop и доступны для трассировки.

enabled_functions

Этот файл больше подходит для отладки ftrace, но может быть полезен и для выяснения функций, с которыми связаны обратные вызовы (callback). Средства трассировки использует не только инфраструктура ftrace, но и другие подсистемы. В этом файле указаны все функции, с которыми связаны callback, а также число обратных вызовов. Отметим, что callback может также вызывать множество функций, которые не учитываются в этом числе.

Если обратный вызов зарегистрирован для трассировки функцией с атрибутом сохранения регистров (save regs), что ведет к добавочному росту издержек, в строке возвращающей регистры функции будет выводиться символ R.

Если обратный вызов зарегистрирован для трассировки функцией с атрибутом ip modify (т. е. regs->ip можно изменить), в строке с функцией, которая может быть переопределена, выводится символ I.

Если архитектура позволяет, будет также показано, для каких callback возможен прямой вызов из функции. Если значение счетчика больше 1, это скорей всего будет ftrace_ops_list_func().

Если обратный вызов функции имеет переход к trampoline2, специфичному для callback, а не к стандартному trampoline, будет выводиться адрес перехода, а также функция, которую вызывает trampoline.

function_profile_enabled

При установке включает отслеживание всех функций с помощью трассировщика function или (если настроен) function_graph. Будет сохраняться гистограмма числа вызовов функций, а при настроенном трассировщике function_graph — еще и время, проведенное в этих функциях. Содержимое гистограммы размещается в файлах по процессорам trace_stat/function<cpu> (function0, function1 и т. д.).

trace_stat

Каталог, в котором хранится статистика трассировки.

kprobe_events

Включает точки динамической трассировки (см. файл kprobetrace.txt в документации ядра).

kprobe_profile

Статистика точек динамической трассировки (см. файл kprobetrace.txt в документации ядра).

max_graph_depth

Применяется с трассировщиком function_graph, задавая максимальную глубину трассировки внутрь функции. При установке в файле значения 1 будет показываться только первый вызов функции ядра из пользовательского пространства.

printk_formats

Этот файл служит для инструментов, читающих необработанные (raw) файлы. Если событие в кольцевом буфере указывается строкой, в буфер записывается лишь указатель, а не сама строка. Это не позволяет инструментам узнать, что было в строке. Данный файл отображает строки и адреса, позволяя инструментам сопоставлять указатели со строками.

saved_cmdlines

В трек событий записывается лишь pid задачи, если событие специально не сохраняет и команду. Ftrace кэширует отображения pid на команды, чтобы попытаться указать для событий и команду. Если pid для команды не указа, выводится <…>.

Если для опции record-cmd установлено значение 0, команды задач не сохраняются при записи. По умолчанию сохранение включено.

saved_cmdlines_size

По умолчанию сохраняется 128 команд (см. saved_cmdlines выше). Для изменения числа кэшируемых команд в этот файл записывается соответствующее число.

saved_tgids

При установленной опции record-tgid для каждого запланированного переключения контекста сохраняется идентификатор группы (Task Group ID) для задачи в таблице сопоставления PID потока с TGID. По умолчанию опция record-tgid выключена.

snapshot

Показывает «моментальный снимок» (snapshot) буфера и позволяет пользователю сделать снимок текущей трассировки (см. раздел Мгновенные снимки).

stack_max_size

При активизации трассировщика стека здесь будет указан максимальный наблюдаемый размер стека (см. раздел Трассировка стека).

stack_trace

Здесь указывается обратная трассировка наибольшего стека, который встретился при активизации трассировщика стека (см. раздел Трассировка стека).

stack_trace_filter

Похоже на set_ftrace_filter, но ограничивает функции, которые будет проверять трассировщик стека.

trace_clock

При записи события в кольцевой буфер указывается временная метка, которая берется из определенных часов. По умолчанию ftrace использует локальные часы (local). Это очень быстрые часы, привязанные к каждому процессору, но они могут быть не синхронизированы между разными CPU.

	  # cat trace_clock
	  [local] global counter x86-tsc

Используемые часы указываются в квадратных скобках.

local

Используемые по умолчанию часы, которые могут быть не синхронизированы между CPU.

global

Эти часы синхронизированы на всех CPU, но могут быть медленней часов local.

counter

Это не часы, а счетчик, увеличивающий значение на 1 и синхронизированный со всеми CPU. Счетчик может быть полезен, когда нужно знать точный порядок событий, связанных с разными CPU.

uptime

Это счетчик циклов jiffy и временная метка относительно момента последней загрузки системы.

perf

Задает для ftrace использование тех же часов, которые применяются perf. В конечном счете perf сможет считывать буферы ftrace buffers и это поможет при чередовании данных.

x86-tsc

Архитектура может задавать свои часы. Например, в x86 применяются часы TSC.

ppc-tb

Значение регистра timebase в powerpc. Оно синхронизировано для всех CPU и может служить для сопоставления событий между гипервизором и гостевыми системами, если известно значение tb_offset.

mono

Быстрый, монотонно возрастающий счетчик (CLOCK_MONOTONIC), согласуемый с NTP .

mono_raw

Быстрый, монотонно возрастающий счетчик (CLOCK_MONOTONIC_RAW) без возможности согласования частоты, работающий от аппаратного генератора сигналов.

boot

Загрузочные часы (CLOCK_BOOTTIME) на основе быстрого монотонно возрастающего счетчика, учитывающие время ожидания. Поскольку доступ к этим часам рассчитан на использование при трассировке на пути с остановками, возможны побочные эффекты при доступе к часам после того, как было учтено время приостановки до обновления монотонно возрастающего счетчика. В 32-битовых системах 64-битовое смещение загрузки может обновляться частично. Эти эффекты возникают редко и постобработка может справляться с ними (см. комментарии в функции ядра ktime_get_boot_fast_ns()).

Для выбора часов просто помещается их имя в файл trace_clock

	  # echo global > trace_clock

trace_marker

Этот файл очень полезен для синхронизации пользовательского пространства с событиями в ядре. Запись строки в этот файл копируется в буфер трассировки ftrace.

Полезно открыть этот файл в приложении при его запуске и просто сослаться на дескриптор файла

		void trace_write(const char *fmt, ...)
		{
			va_list ap;
			char buf[256];
			int n;

			if (trace_fd < 0)
				return;

			va_start(ap, fmt);
			n = vsnprintf(buf, 256, fmt, ap);
			va_end(ap);

			write(trace_fd, buf, n);
		}

	start::

		trace_fd = open("trace_marker", WR_ONLY);

Примечание. Запись в файл trace_marker будет также вызывать запись в /sys/kernel/tracing/events/ftrace/print/trigger (см. Event triggers в файле Documentation/trace/events.rst и пример в разделе 3 файла trace/histogram.rst)

trace_marker_raw

Похож на trace_marker, но предназначен для записи двоичных данных, когда можно использовать инструмент для анализа.

uprobe_events

Добавляет в программу динамические точки трассировки (см. uprobetracer.txt).

uprobe_profile

Статистика uprobe (см. uprobetracer.txt).

instances

Это способ создания множества буферов трассировки, куда могут записываться разные события (см. Экземпляры).

events

Это каталог событий трассировки, в котором хранятся события точек трассировки (статические точки трассировки), встроенных в ядро. Это показывает наличие точек трассировки и их группировку в системе. Здесь расположены файлы «разрешения» для различных уровней, которые позволяют включить точки трассировки при записи 1 в соответствующий файл (см. events.txt).

set_event

Запись события в этот файл будет разрешать трассировку этого события (см. events.txt).

available_events

Список событий, трассировка которых может быть включена (см. events.txt).

timestamp_mode

Некоторые трассировщики могут менять режим временных меток, используемый при записи событий в кольцевой буфер. События с разными режимами меток могут сосуществовать в буфере, но действующий режим влияет на временную метку, записываемую с событием. По умолчанию применяется режим меток delta (приращение).

	  # cat timestamp_mode
	  [delta] absolute

В квадратных скобках указывается действующий режим временных меток.

delta

Указывается интервал времени от предшествующего события в данном буфере. Применяется по умолчанию.

absolute

Временная метка содержит полное время, а не приращение от предыдущего значения. Эти метки занимают больше места и менее эффективны.

hwlat_detector

Каталог для детектора задержек в оборудовании (см. Определение аппаратной задержки).

per_cpu

Каталог с данными трассировки для каждого процессора. В качестве примера показан процессор 0.

per_cpu/cpu0/buffer_size_kb

Размер буфера ftrace для данного процессора. Отдельные буферы позволяют каждому процессору записывать данные самостоятельно без общего кэширования. Буферы разных процессоров могут различаться по размеру. Этот файл поход на buffer_size_kb file, но показывает размер буфера отдельного процессора.

per_cpu/cpu0/trace

Похож на файл trace, но отображает данные лишь для одного CPU. При записи очищается буфер только данного CPU.

per_cpu/cpu0/trace_pipe

Похож на trace_pipe и «потребляет» данные при чтении, но отображает (и потребляет) данные лишь одного CPU.

per_cpu/cpu0/trace_pipe_raw

Для инструментов, понимающих двоичный формат кольцевого буфера ftrace, файл trace_pipe_raw может служить для извлечения информации напрямую из кольцевого буфера. С помощью системного вызова splice() данные из буфера можно быстро перенести в файл или сеть для сбора на сервере.

Подобно trace_pipe, это потребляющий считыватель, где каждое чтение будет возвращать новые данные.

per_cpu/cpu0/snapshot

Похож на файл snapshot, но дает снимок только для одного CPU (если это поддерживается). При записи в файл очищается только буфер данного CPU.

per_cpu/cpu0/snapshot_raw

Похож на trace_pipe_raw, но считывает двоичные данные лишь из «моментального снимка» для данного CPU.

per_cpu/cpu0/stats

Статистика из кольцевого буфера процессора.

entries

Число событий, остающихся в буфере.

overrun

Число перезаписанных событий в результате заполнения буфера.

commit overrun

Значение в файле устанавливается, если произошло много событий внутри вложенного события (повторный вход в кольцевой буфер), заполнивших буфер и приведших к отбрасыванию событий. В нормальных условиях содержит 0.

bytes

Число реально прочитанных байтов (не перезаписанных).

oldest event ts

Временная метка самого старого события в буфере.

now ts

Текущая временная метка.

dropped events

События, потерянные в результате выключения опции перезаписи.

read events

Число
считываний событий
.

Трассировщики

Ниже приведен список трассировщиков, которые могут быть настроены в системе.

function

Трассировщик
вызовов для всех функций ядра.

function_graph

Похож на трассировщик function, но отличается дополнительным отслеживанием выхода из функции, которое первый не выполняет. Это позволяет построить граф вызовов функций, похожий на исходный код языка C.

blk

Трассировщик блоков, применяемый пользовательским приложением blktrace.

hwlat

Трассировщик аппаратной задержки, служащий для обнаружения задержки в оборудовании. (см. Определение аппаратной задержки).

irqsoff

Трассирует области, где запрещены прерывания и сохранеяет вызов с самой большой максимальной задержкой, заменяя имеющееся значение, если новый максимум превышает его. Лучше всего использовать эту трассировку со включенной опцией latency-format, которая автоматически включается при выборе трассировщика.

Этот трассировщик похож на preemptirqsoff,
но отслеживает
лишь максимальный интервал запрета
прерываний
.

preemptoff

Похож на трассировщик preemptirqsoff,
но отслеживает
лишь максимальный интервал запрета
вытеснения
.

preemptirqsoff

Похож на irqsoff и preemptoff, но трассирует и записывает лишь наибольшее время, когда irq и/или вытеснение были отключены.

wakeup

Трассировка максимальной задержки между пробуждением процесса с наивысшим приоритетом и запланированным его использованием.

wakeup_rt

Трассировка максимальной задержки между пробуждением процесса с наивысшим приоритетом и запланированным его использованием. Этот трассировщик отслеживает лишь задачи, работающие в режиме реального времени (RT3), а задачи SCHED_OTHER игнорируются.

wakeup_dl

Отслеживает и записывает максимальную задержку для задач SCHED_DEADLINE (подобно wakeup и wakeup_rt).

mmiotrace

Специальный трассировщий, служащий для отслеживания двоичных модулей. Он будет отслеживать все вызовы, которые модуль делает для оборудования.

branch

Этот трассировщик можно настроит на вероятные и маловероятные вызовы внутри ядра. Он будет отслеживать вероятные и маловероятные ветвления и оценивать корректность их предсказания.

nop

Отключает трассировку. Для выключения всех трассировщиков достаточно просто записать nop в файл current_tracer.

Примеры использования трассировщиков

Здесь представлены типовые примеры использования трассировщиков с управлением лишь через интерфейс tracefs (без утилит пользовательского пространства).

Выходной формат

Ниже представлен пример выходного формата файла трассировки (trace).

  # tracer: function
  #
  # entries-in-buffer/entries-written: 140080/250280   #P:4
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |
              bash-1977  [000] .... 17284.993652: sys_close <-system_call_fastpath
              bash-1977  [000] .... 17284.993653: __close_fd <-sys_close
              bash-1977  [000] .... 17284.993653: _raw_spin_lock <-__close_fd
              sshd-1974  [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
              bash-1977  [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
              bash-1977  [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
              bash-1977  [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
              bash-1977  [000] .... 17284.993657: filp_close <-__close_fd
              bash-1977  [000] .... 17284.993657: dnotify_flush <-filp_close
              sshd-1974  [003] .... 17284.993658: sys_select <-system_call_fastpath
              ....

Заголовок выводится с именем трассировщика (в примере function). Затем выводится число событий в буфере и общее число сделанных записей. Разница между этими значениями показывает число потерянных событий (250280 — 140080 = 110200 потерянных событий).

В заголовке разъясняется содержимое событий. Имя задачи bash, ее идентификатор PID — 1977, задача работает на CPU 000, задержка (формат описан ниже, временная метка в формате <сек>.<мксек>, имя отслеживаемой функции (sys_close и родительская функция system_call_fastpath). Временная метка показывает момент входа в функцию.

Формат трассировки задержек

При включенной опции latency-format или установке одного из трассировщиков задержки файл trace содержит дополнительную информацию, позволяющую увидеть причину задержки. Ниже приведен пример трассировки.

  # tracer: irqsoff
  #
  # irqsoff latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
  #    -----------------
  #  => started at: __lock_task_sighand
  #  => ended at:   _raw_spin_unlock_irqrestore
  #
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
        ps-6143    2d...    0us!: trace_hardirqs_off <-__lock_task_sighand
        ps-6143    2d..1  259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
        ps-6143    2d..1  263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
        ps-6143    2d..1  306us : <stack trace>
   => trace_hardirqs_on_caller
   => trace_hardirqs_on
   => _raw_spin_unlock_irqrestore
   => do_task_stat
   => proc_tgid_stat
   => proc_single_show
   => seq_read
   => vfs_read
   => sys_read
   => system_call_fastpath

Вывод показывает, что трассировщик irqsoff отслеживает время, на которое отключались прерывания. Указана версия трассировки (никогда не меняется) и версия ядра (3.8). Затем указана максимальная задержка в микросекундах (259), число показанных событий и общее их число (#4/4). VP, KP, SP и HP всегда имеют значение 0 (резерв на будущее). #P указывает число работающих процессоров CPU (#P:4).

В качестве задачи указывается процесс, который работал при возникновении задержки (ps pid: 6143).

Строки started at и ended at указывают функции, в которых прерывания были отключены и включены (соответственно), что и привело к задержке.

  • В функции __lock_task_sighand прерывания были отключены.

  • В функции _raw_spin_unlock_irqrestore прерывания были снова включены.

Далее следует заголовок, разъясняющий формат вывода, и результаты трассировки.

cmd

Имя процесса в трассировке.

pid

PID этого процесса.

CPU#

Номер CPU, на котором выполнялся процесс.

irqs-off

Символ d указывает запрет прерываний, в остальных случаях выводится точка (.). Если архитектура не поддерживает считывание переменной флагов irq, в этом поле всегда указывается символ X.

need-resched

  • N — установлены оба флага TIF_NEED_RESCHED и PREEMPT_NEED_RESCHED;
  • n — установлен только флаг TIF_NEED_RESCHED;
  • p — установлен только флаг PREEMPT_NEED_RESCHED;
  • . — иное.

hardirq/softirq

  • Z — прерывание NMI внутри hardirq;
  • z — NMI выполняется;
  • H — аппаратное irq внутри softirq;
  • h — аппаратное irq выполняется;
  • s — программное irq выполняется;
  • . — обычный контекст.

preempt-depth

Уровень preempt_disabled.

Описанное выше предназначено в основном для разработчиков ядра.

time:

При включенной опции latency-format вывод файла trace включает временные метки относительно начала трассировки, а при выключенной опции latency-format метки указываются в абсолютном времени.

delay

Это просто метки для упрощения зрительного восприятия, относящиеся к одному CPU и показывающие разницу между текущей и следующей трассировкой.

  • $ — больше 1 секунды;
  • @ — больше 100 миллисекунд;
  • * — больше 10 миллисекунд;
  • # — больше 1000 микросекунд;
  • ! — больше 100 микросекунд;
  • + — больше 10 микросекунд;
  • ‘ ‘ — не больше 10 микросекунд.

Остальная часть вывода такая же как для файла trace.

Отметим, что трассировщики задержки обычно завершаются трассировкой назад, чтобы было увидеть место задержки.

Опции трассировки — файл trace_options

Файл trace_options (или каталог options) служит для управления выводом трассировки или манипуляций с трассировщиками. Для просмотра доступного просто введите команду cat.

  cat trace_options
	print-parent
	nosym-offset
	nosym-addr
	noverbose
	noraw
	nohex
	nobin
	noblock
	trace_printk
	annotate
	nouserstacktrace
	nosym-userobj
	noprintk-msg-only
	context-info
	nolatency-format
	record-cmd
	norecord-tgid
	overwrite
	nodisable_on_free
	irq-info
	markers
	noevent-fork
	function-trace
	nofunction-fork
	nodisplay-graph
	nostacktrace
	nobranch

Для отключения нужной опции добавьте к ее имени префикс no и отправьте в файл trace_options4

  echo noprint-parent > trace_options

Для включения опции отправьте ее имя в файл trace_options

  echo sym-offset > trace_options

Список доступных опций приведен ниже.

print-parent

При трассировке функций задает вывод вызывающей (родительской) функции вместе с трассируемой.

print-parent

	   bash-4000  [01]  1477.606694: simple_strtoul <-kstrtoul

noprint-parent

	   bash-4000  [01]  1477.606694: simple_strtoul

sym-offset

Вывод не только имени функции, но и ее смещения. Например, вместо ktime_get будет ktime_get+0xb/0x20.

sym-offset

	   bash-4000  [01]  1477.606694: simple_strtoul+0x6/0xa0

sym-addr

Вывод адреса функции вместе с ее именем.

sym-addr

	   bash-4000  [01]  1477.606694: simple_strtoul <c0339346>

verbose

Задает подробный вывод в файле trace при включенной опции latency-format.

     bash  4000 1 0 00000000 00010a95 [58127d26] 1720.415ms  (+0.000ms): simple_strtoul (kstrtoul)

raw

Вывод необработанных (raw) чисел. Эта опция удобна для использования с приложениями, транслирующими необработанные числа лучше, чем это делает ядро.

hex

Похожа на raw, но числа выводятся в шестнадцатеричном формате.

bin

Вывод в необработанном двоичном формате.

block

При установленной опции считывание файла trace_pipe не будет блокироваться при опросе.

trace_printk

Может запрещать запись trace_printk() в буфер.

annotate

При заполненных буферах CPU может возникать путаница, когда в одном буфере имеется много свежих событий, а у другого событий немного и буфер будет содержать более старые события. При выводе трассировки сначала указываются более старые события и может показаться, что работает лишь один процессор. При включенном аннотировании будет указываться запуск нового буфера CPU.

			  <idle>-0     [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
			  <idle>-0     [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
			  <idle>-0     [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
		##### CPU 2 buffer started ####
			  <idle>-0     [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
			  <idle>-0     [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
			  <idle>-0     [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock

userstacktrace

Эта опция меняет трассировку и ведет к записи трассировки стека (stacktrace) текущего потока пользовательского пространства после каждого трассируемого события.

sym-userobj

При включенной опции userstacktrace определяется, к какому объекту относится адрес и выводится относительный адрес. Это особенно полезно при включенном ASLR, поскольку иначе не будет возможности преобразовать адрес в объект/файл/строку после того, как приложение прекратит работу. Поиск выполняется при чтении trace или trace_pipe.

		  a.out-1623  [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
		  x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]

printk-msg-only

При установке этой опции trace_printk() будет показывать только формат, а не параметры (если использовался вызов trace_bprintk() или trace_bputs() для сохранения trace_printk()).

context-info

Задает вывод только событий без команд, PID, временных меток, CPU и других данных.

latency-format

Эта опция меняет вывод трассировки и при включении обеспечивает дополнительную информацию о задержке, как описано в разделе Формат трассировки задержек.

record-cmd

При включении любого события или трассировщика в точке трассировки sched_switch включается ловушка для заполнения кэша сопоставлений pid и команд. Однако это может приводить к издержкам и если вам достаточно pid без имен задач, отключение этой опции может снизить влияние на трассировку (см. saved_cmdlines).

record-tgid

При включении любого события или трассировщика в точке трассировки sched_switch включается ловушка для заполнения кэша сопоставлений pid и TGID5 (см. saved_tgids).

overwrite

Управляет поведением при заполнении буфера трассировки. Значение 1 (принято по умолчанию) ведет к перезаписи самых старых событий, 0 — к перезаписи самых новых (см. per_cpu/cpu0/stats, где указаны переполнения и отбрасывания).

disable_on_free

При закрытии free_buffer трассировка будет прекращаться (устанавливается tracing_on = 0).

irq-info

Показывает прерывание, счетчик вытеснения и необходимость перепланировки данных. При отключенной опции трассировка будет иметь вид

# tracer: function
#
# entries-in-buffer/entries-written: 144405/9452052   #P:4
#
#           TASK-PID   CPU#      TIMESTAMP  FUNCTION
#              | |       |          |         |
	  <idle>-0     [002]  23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
	  <idle>-0     [002]  23636.756054: activate_task <-ttwu_do_activate.constprop.89
	  <idle>-0     [002]  23636.756055: enqueue_task <-activate_task

markers

Установка опции открывает файл trace_marker для записи (пользователю root). При отключенной опции запись в trace_marker будет приводить к ошибке EINVAL.

event-fork

При установке опции для задач, PID которых указаны в set_event_pid, в этот файл будут добавляться при ветвлении PID дочерних процессов. При завершении задачи с PID, указанным в set_event_pid, значение PID будет удаляться из файла.

function-trace

При включенной опции трассировщики задержек будут включать трассировку функций (принято по умолчанию). Если опция не установлена при трассировке задержки функции отслеживаться не будут для снижения издержек.

function-fork

При установке опции для задач, PID которых указаны в set_ftrace_pid, в этот файл будут добавляться при ветвлении PID дочерних процессов. При завершении задачи с PID, указанным в set_ftrace_pid exit, значение PID будет удаляться из файла.

display-graph

При включенной опции трассировщик задержек (irqsoff, wakeup и т. п.) будет применять трассировку function_graph вместо function.

stacktrace

При включенной опции записывается трассировка стека после записи любого события.

branch

Разрешает трассировку ветвления, включая трассировщик branch вместе с текущим трассировщиком. Включение этой опции с трассировщиком nop эквивалентно простому включению трассировщика branch.

Примечание. У некоторых трассировщиков имеются свои опции, которые выводятся в файле только при их активизации. Однако они всегда присутствуют в каталоге options.

Ниже рассматриваются опции отдельных трассировщиков.

Опции трассировщика function

func_stack_trace

При установке этой опции записывается трассировка стека после записи каждой функции. Перед включением этой опции важно ограничить число отслеживаемых функций с помощью фильтра set_ftrace_filter, поскольку иначе производительность системы сильно снизится. Не забывает отключить эту опцию до отмены фильтра отслеживаемых функций.

Опции трассировщика function_graph

Поскольку трассировщик function_graph отличается выводом, у него имеются свои опции для контроля вывода.

funcgraph-overrun

При установке опции «переполнение» стека function_graph отображается после каждой отслеживаемой функции. Переполнение возникает, когда грубина стека вызовов превышает значение, зарезервированное для каждой задачи. Каждая задача имеет фиксированный массив функций для отслеживания в графе вызовов. Если глубина вызовов превышает предел, функция не отслеживается. Переполнение — это число функций, пропущенных в результате превышения массива.

funcgraph-cpu

При установке опции отображается номер CPU, где выполнялась трассировка.

funcgraph-overhead

При установленной опции отображается маркер задержки, если функция заняла время, превышающее некое значение.

funcgraph-proc

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

funcgraph-duration

В конце каждой функции (возврат) выводится продолжительность ее работы в микросекундах.

funcgraph-abstime

При установке опции в каждой строке выводится временная метка.

funcgraph-irqs

При отключенной опции функции внутри прерываний не отслеживаются.

funcgraph-tail

При установленной опции событие возврата будет включать представляемую им функцию. По умолчанию это отключено и при возврате из функции отображается лишь фигурная скобка }.

sleep-time

Служит для учета запланированного времени задачи при работе трассировщика function_graph. При включенной опции запланированное время будет учитываться как часть вызова функции.

graph-time

При запуске профилировщика функций с трассировщиком function_graph служит для включения времени вызова вложенных функций. Если опция не задана, указываемое для функции время будет включать только время выполнения самой функции без учета вызываемых ею функций.

Опции трассировщика blk

  blk_classic

Задает минимальный
вывод
.

Трассировщик irqsoff

При отключенных прерываниях CPU не может реагировать на другие внешние события, кроме NMI и SMI. В результате замедляется реакция системы на события.

Трассировщик irqsoff отслеживает периоды запрета прерываний. При достижении нового значения максимальной задержки трассировщик сохраняет трассировку к точке задержки, чтобы при достижении нового максимума прежнее значения отбрасывалось, а новое записывалось.

Для сброса максимума записывается значение 0 в файл tracing_max_latency. Ниже приведен пример.

  # echo 0 > options/function-trace
  # echo irqsoff > current_tracer
  # echo 1 > tracing_on
  # echo 0 > tracing_max_latency
  # ls -ltr
  [...]
  # echo 0 > tracing_on
  # cat trace
  # tracer: irqsoff
  #
  # irqsoff latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
  #    -----------------
  #  => started at: run_timer_softirq
  #  => ended at:   run_timer_softirq
  #
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
    <idle>-0       0d.s2    0us+: _raw_spin_lock_irq <-run_timer_softirq
    <idle>-0       0dNs3   17us : _raw_spin_unlock_irq <-run_timer_softirq
    <idle>-0       0dNs3   17us+: trace_hardirqs_on <-run_timer_softirq
    <idle>-0       0dNs3   25us : <stack trace>
   => _raw_spin_unlock_irq
   => run_timer_softirq
   => __do_softirq
   => call_softirq
   => do_softirq
   => irq_exit
   => smp_apic_timer_interrupt
   => apic_timer_interrupt
   => rcu_idle_exit
   => cpu_idle
   => rest_init
   => start_kernel
   => x86_64_start_reservations
   => x86_64_start_kernel

Вывод показывает задержку 16 мксек (очень хорошо). Прерывания отключены функцией _raw_spin_lock_irq в run_timer_softirq. Разница между задержкой в 16 мксек и показанной временной меткой 25us обусловлена инкрементированием часов между моментами записи максимальной задержки и функции, вызвавшей эту задержку.

Отметим, что в приведенном выше примере опция function-trace не была установлена и при ее установке вывод будет более подробным, как показано ниже.

 with echo 1 > options/function-trace
  # tracer: irqsoff
  #
  # irqsoff latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
  #    -----------------
  #  => started at: ata_scsi_queuecmd
  #  => ended at:   ata_scsi_queuecmd
  #
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
      bash-2042    3d...    0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
      bash-2042    3d...    0us : add_preempt_count <-_raw_spin_lock_irqsave
      bash-2042    3d..1    1us : ata_scsi_find_dev <-ata_scsi_queuecmd
      bash-2042    3d..1    1us : __ata_scsi_find_dev <-ata_scsi_find_dev
      bash-2042    3d..1    2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
      bash-2042    3d..1    2us : ata_qc_new_init <-__ata_scsi_queuecmd
      bash-2042    3d..1    3us : ata_sg_init <-__ata_scsi_queuecmd
      bash-2042    3d..1    4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
      bash-2042    3d..1    4us : ata_build_rw_tf <-ata_scsi_rw_xlat
  [...]
      bash-2042    3d..1   67us : delay_tsc <-__delay
      bash-2042    3d..1   67us : add_preempt_count <-delay_tsc
      bash-2042    3d..2   67us : sub_preempt_count <-delay_tsc
      bash-2042    3d..1   67us : add_preempt_count <-delay_tsc
      bash-2042    3d..2   68us : sub_preempt_count <-delay_tsc
      bash-2042    3d..1   68us+: ata_bmdma_start <-ata_bmdma_qc_issue
      bash-2042    3d..1   71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
      bash-2042    3d..1   71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
      bash-2042    3d..1   72us+: trace_hardirqs_on <-ata_scsi_queuecmd
      bash-2042    3d..1  120us : <stack trace>
   => _raw_spin_unlock_irqrestore
   => ata_scsi_queuecmd
   => scsi_dispatch_cmd
   => scsi_request_fn
   => __blk_run_queue_uncond
   => __blk_run_queue
   => blk_queue_bio
   => generic_make_request
   => submit_bio
   => submit_bh
   => __ext3_get_inode_loc
   => ext3_iget
   => ext3_lookup
   => lookup_real
   => __lookup_hash
   => walk_component
   => lookup_last
   => path_lookupat
   => filename_lookup
   => user_path_at_empty
   => user_path_at
   => vfs_fstatat
   => vfs_stat
   => sys_newstat
   => system_call_fastpath

Здесь показана задержка в 71 мксек, но видны функции, которые вызвались в это время. Отметим, что включение трассировки функций увеличило издержки, которые могли привести к росту задержки. Тем не менее, эта трассировка содержит много полезной для отладки информации.

Трассировщик preemptoff

При отключенном вытеснении (preemption) прерывания будут работать, но задачи не могут вытеснять друг друга и в результате задаче с высоким приоритетом может потребоваться ожидать возможности вытеснения менее приоритетной задачи.

Трассировщик preemptoff отслеживает места, где вытеснение запрещено. Подобно трассировщику irqsoff, он записывает максимальную задержку, для которой вытеснение было отключено. Управление трассировщиком preemptoff похоже на управление irqsoff.

  # echo 0 > options/function-trace
  # echo preemptoff > current_tracer
  # echo 1 > tracing_on
  # echo 0 > tracing_max_latency
  # ls -ltr
  [...]
  # echo 0 > tracing_on
  # cat trace
  # tracer: preemptoff
  #
  # preemptoff latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
  #    -----------------
  #  => started at: do_IRQ
  #  => ended at:   do_IRQ
  #
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
      sshd-1991    1d.h.    0us+: irq_enter <-do_IRQ
      sshd-1991    1d..1   46us : irq_exit <-do_IRQ
      sshd-1991    1d..1   47us+: trace_preempt_on <-do_IRQ
      sshd-1991    1d..1   52us : <stack trace>
   => sub_preempt_count
   => irq_exit
   => do_IRQ
   => ret_from_intr

Здесь видны некоторые отличия. Вытеснение было отключено во время прерывания (символ h) и восстановлено по завершении. Однако можно видеть, что прерывания были отключены при входе в раздел preempt off и на выходе из него (символ d). Неизвестно, были ли прерывания включены в это время или вскоре после него.

  # tracer: preemptoff
  #
  # preemptoff latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
  #    -----------------
  #  => started at: wake_up_new_task
  #  => ended at:   task_rq_unlock
  #
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
      bash-1994    1d..1    0us : _raw_spin_lock_irqsave <-wake_up_new_task
      bash-1994    1d..1    0us : select_task_rq_fair <-select_task_rq
      bash-1994    1d..1    1us : __rcu_read_lock <-select_task_rq_fair
      bash-1994    1d..1    1us : source_load <-select_task_rq_fair
      bash-1994    1d..1    1us : source_load <-select_task_rq_fair
  [...]
      bash-1994    1d..1   12us : irq_enter <-smp_apic_timer_interrupt
      bash-1994    1d..1   12us : rcu_irq_enter <-irq_enter
      bash-1994    1d..1   13us : add_preempt_count <-irq_enter
      bash-1994    1d.h1   13us : exit_idle <-smp_apic_timer_interrupt
      bash-1994    1d.h1   13us : hrtimer_interrupt <-smp_apic_timer_interrupt
      bash-1994    1d.h1   13us : _raw_spin_lock <-hrtimer_interrupt
      bash-1994    1d.h1   14us : add_preempt_count <-_raw_spin_lock
      bash-1994    1d.h2   14us : ktime_get_update_offsets <-hrtimer_interrupt
  [...]
      bash-1994    1d.h1   35us : lapic_next_event <-clockevents_program_event
      bash-1994    1d.h1   35us : irq_exit <-smp_apic_timer_interrupt
      bash-1994    1d.h1   36us : sub_preempt_count <-irq_exit
      bash-1994    1d..2   36us : do_softirq <-irq_exit
      bash-1994    1d..2   36us : __do_softirq <-call_softirq
      bash-1994    1d..2   36us : __local_bh_disable <-__do_softirq
      bash-1994    1d.s2   37us : add_preempt_count <-_raw_spin_lock_irq
      bash-1994    1d.s3   38us : _raw_spin_unlock <-run_timer_softirq
      bash-1994    1d.s3   39us : sub_preempt_count <-_raw_spin_unlock
      bash-1994    1d.s2   39us : call_timer_fn <-run_timer_softirq
  [...]
      bash-1994    1dNs2   81us : cpu_needs_another_gp <-rcu_process_callbacks
      bash-1994    1dNs2   82us : __local_bh_enable <-__do_softirq
      bash-1994    1dNs2   82us : sub_preempt_count <-__local_bh_enable
      bash-1994    1dN.2   82us : idle_cpu <-irq_exit
      bash-1994    1dN.2   83us : rcu_irq_exit <-irq_exit
      bash-1994    1dN.2   83us : sub_preempt_count <-irq_exit
      bash-1994    1.N.1   84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
      bash-1994    1.N.1   84us+: trace_preempt_on <-task_rq_unlock
      bash-1994    1.N.1  104us : <stack trace>
   => sub_preempt_count
   => _raw_spin_unlock_irqrestore
   => task_rq_unlock
   => wake_up_new_task
   => do_fork
   => sys_clone
   => stub_clone

Выше приведен пример трассировки preemptoff с включенной опцией function-trace. Здесь видно, что прерывания были отключены не все время. Код irq_enter указывает вход в прерывание h. Перед этим отслеживаемые функции показывают, что они не находятся в прерывании, но из самих функций видно, что это не так.

Трассировщик preemptirqsoff

Полезно знать места, где прерывания или вытеснение были отключены на самое продолжительное время. Однако иногда нужно знать, когда прерывания и/или вытеснение были отключены. Рассмотрим пример кода.

    local_irq_disable();
    call_function_with_irqs_off();
    preempt_disable();
    call_function_with_irqs_and_preemption_off();
    local_irq_enable();
    call_function_with_preemption_off();
    preempt_enable();

Трассировщик irqsoff записывает общую продолжительность вызовов call_function_with_irqs_off() и call_function_with_irqs_and_preemption_off(), preemptoff — общую продолжительность call_function_with_irqs_and_preemption_off() и call_function_with_preemption_off(). Но ни один из них не записывает время, в течение которого прерывания и/или вытеснение были отключены. Это общее время, которое мы не можем планировать. Для записи этого времени служит трассировщик preemptirqsoff.

Работа с этим трассировщиком похожа на действия с irqsoff и preemptoff.

  # echo 0 > options/function-trace
  # echo preemptirqsoff > current_tracer
  # echo 1 > tracing_on
  # echo 0 > tracing_max_latency
  # ls -ltr
  [...]
  # echo 0 > tracing_on
  # cat trace
  # tracer: preemptirqsoff
  #
  # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
  #    -----------------
  #  => started at: ata_scsi_queuecmd
  #  => ended at:   ata_scsi_queuecmd
  #
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
        ls-2230    3d...    0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
        ls-2230    3...1  100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
        ls-2230    3...1  101us+: trace_preempt_on <-ata_scsi_queuecmd
        ls-2230    3...1  111us : <stack trace>
   => sub_preempt_count
   => _raw_spin_unlock_irqrestore
   => ata_scsi_queuecmd
   => scsi_dispatch_cmd
   => scsi_request_fn
   => __blk_run_queue_uncond
   => __blk_run_queue
   => blk_queue_bio
   => generic_make_request
   => submit_bio
   => submit_bh
   => ext3_bread
   => ext3_dir_bread
   => htree_dirblock_to_tree
   => ext3_htree_fill_tree
   => ext3_readdir
   => vfs_readdir
   => sys_getdents
   => system_call_fastpath

Вызов trace_hardirqs_off_thunk выполняется из сборки кода x86 когда прерывания запрещены в этой сборке. Без трассировки функций мы не узнаем, были ли прерывания запрещены в пределах точек вытеснения. Видно, что это начинается с включения вытеснения. Ниже показана трассировка с включенной опцией function-trace.

  # tracer: preemptirqsoff
  #
  # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
  #    -----------------
  #  => started at: schedule
  #  => ended at:   mutex_unlock
  #
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
  kworker/-59      3...1    0us : __schedule <-schedule
  kworker/-59      3d..1    0us : rcu_preempt_qs <-rcu_note_context_switch
  kworker/-59      3d..1    1us : add_preempt_count <-_raw_spin_lock_irq
  kworker/-59      3d..2    1us : deactivate_task <-__schedule
  kworker/-59      3d..2    1us : dequeue_task <-deactivate_task
  kworker/-59      3d..2    2us : update_rq_clock <-dequeue_task
  kworker/-59      3d..2    2us : dequeue_task_fair <-dequeue_task
  kworker/-59      3d..2    2us : update_curr <-dequeue_task_fair
  kworker/-59      3d..2    2us : update_min_vruntime <-update_curr
  kworker/-59      3d..2    3us : cpuacct_charge <-update_curr
  kworker/-59      3d..2    3us : __rcu_read_lock <-cpuacct_charge
  kworker/-59      3d..2    3us : __rcu_read_unlock <-cpuacct_charge
  kworker/-59      3d..2    3us : update_cfs_rq_blocked_load <-dequeue_task_fair
  kworker/-59      3d..2    4us : clear_buddies <-dequeue_task_fair
  kworker/-59      3d..2    4us : account_entity_dequeue <-dequeue_task_fair
  kworker/-59      3d..2    4us : update_min_vruntime <-dequeue_task_fair
  kworker/-59      3d..2    4us : update_cfs_shares <-dequeue_task_fair
  kworker/-59      3d..2    5us : hrtick_update <-dequeue_task_fair
  kworker/-59      3d..2    5us : wq_worker_sleeping <-__schedule
  kworker/-59      3d..2    5us : kthread_data <-wq_worker_sleeping
  kworker/-59      3d..2    5us : put_prev_task_fair <-__schedule
  kworker/-59      3d..2    6us : pick_next_task_fair <-pick_next_task
  kworker/-59      3d..2    6us : clear_buddies <-pick_next_task_fair
  kworker/-59      3d..2    6us : set_next_entity <-pick_next_task_fair
  kworker/-59      3d..2    6us : update_stats_wait_end <-set_next_entity
        ls-2269    3d..2    7us : finish_task_switch <-__schedule
        ls-2269    3d..2    7us : _raw_spin_unlock_irq <-finish_task_switch
        ls-2269    3d..2    8us : do_IRQ <-ret_from_intr
        ls-2269    3d..2    8us : irq_enter <-do_IRQ
        ls-2269    3d..2    8us : rcu_irq_enter <-irq_enter
        ls-2269    3d..2    9us : add_preempt_count <-irq_enter
        ls-2269    3d.h2    9us : exit_idle <-do_IRQ
  [...]
        ls-2269    3d.h3   20us : sub_preempt_count <-_raw_spin_unlock
        ls-2269    3d.h2   20us : irq_exit <-do_IRQ
        ls-2269    3d.h2   21us : sub_preempt_count <-irq_exit
        ls-2269    3d..3   21us : do_softirq <-irq_exit
        ls-2269    3d..3   21us : __do_softirq <-call_softirq
        ls-2269    3d..3   21us+: __local_bh_disable <-__do_softirq
        ls-2269    3d.s4   29us : sub_preempt_count <-_local_bh_enable_ip
        ls-2269    3d.s5   29us : sub_preempt_count <-_local_bh_enable_ip
        ls-2269    3d.s5   31us : do_IRQ <-ret_from_intr
        ls-2269    3d.s5   31us : irq_enter <-do_IRQ
        ls-2269    3d.s5   31us : rcu_irq_enter <-irq_enter
  [...]
        ls-2269    3d.s5   31us : rcu_irq_enter <-irq_enter
        ls-2269    3d.s5   32us : add_preempt_count <-irq_enter
        ls-2269    3d.H5   32us : exit_idle <-do_IRQ
        ls-2269    3d.H5   32us : handle_irq <-do_IRQ
        ls-2269    3d.H5   32us : irq_to_desc <-handle_irq
        ls-2269    3d.H5   33us : handle_fasteoi_irq <-handle_irq
  [...]
        ls-2269    3d.s5  158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
        ls-2269    3d.s3  158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
        ls-2269    3d.s3  159us : __local_bh_enable <-__do_softirq
        ls-2269    3d.s3  159us : sub_preempt_count <-__local_bh_enable
        ls-2269    3d..3  159us : idle_cpu <-irq_exit
        ls-2269    3d..3  159us : rcu_irq_exit <-irq_exit
        ls-2269    3d..3  160us : sub_preempt_count <-irq_exit
        ls-2269    3d...  161us : __mutex_unlock_slowpath <-mutex_unlock
        ls-2269    3d...  162us+: trace_hardirqs_on <-mutex_unlock
        ls-2269    3d...  186us : <stack trace>
   => __mutex_unlock_slowpath
   => mutex_unlock
   => process_output
   => n_tty_write
   => tty_write
   => vfs_write
   => sys_write
   => system_call_fastpath

Эта интересная трассировка, которая начинается с того, что процесс kworker работает и запланирован, но ls берет управление на себя. Как только ls освобождает rq и разрешает прерывания (но не вытеснение), сразу срабатывает прерывание. По завершении прерывания запускаются softirq, но во время работы softirq происходит другое прерывание, завершение которого внутри softirq указывается символом H.

Трассировщик wakeup

Одним из основных случаев, представляющих интерес для отслеживания, является время, требуемое для выполнения задачи, которая пробуждается для реальной работы. Это не задачи в реальном масштабе времени (RT), а обычные задачи. Но их трассировка не менее интересна.

Ниже приведена трассировка без отслеживания функций.

  # echo 0 > options/function-trace
  # echo wakeup > current_tracer
  # echo 1 > tracing_on
  # echo 0 > tracing_max_latency
  # chrt -f 5 sleep 1
  # echo 0 > tracing_on
  # cat trace
  # tracer: wakeup
  #
  # wakeup latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
  #    -----------------
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
    <idle>-0       3dNs7    0us :      0:120:R   + [003]   312:100:R kworker/3:1H
    <idle>-0       3dNs7    1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
    <idle>-0       3d..3   15us : __schedule <-schedule
    <idle>-0       3d..3   15us :      0:120:R ==> [003]   312:100:R kworker/3:1H

Трассировщик отслеживат лишь задачи с наиболее высоким приоритетом в системе, не трассируя обычные ситуации. Можно видеть, что для задачи kworker с приоритетом nice = of -20 (не очень высокий) прошло лишь 15 мксек между пробуждением и началом работы.

Задачи, не работающие в режиме реального времени (RT), не так интересны, по сравнению с задачами RT.

Трассировщик wakeup_rt

В среде RT очень важно знать, какое время проходит между пробуждением задачи с наивысшим приоритетом и началом ее выполнения. Это время называют также задержкой планирования (schedule latency). Подчеркнем, что речь здесь идет только о задачах RT. Важно также понимать задержку планирования для задач не-RT, но для них лучше средняя задержка планирования. Для таких измерений лучше подходят такие инструменты, как LatencyTop.

Для сред RT интересна задержка в худшей ситуации. Это наибольшая, а не средняя задержка. У нас может быть очень быстрый планировщик, который будет редко приводить к значительным задержкам, но он может быть недостаточно хорош для задач RT. Трассировщик wakeup_rt был разработан для определения худшего варианта пробуждения задач RT. Другие (не-RT) задачи не отслеживаются, поскольку трассировщик записывает один наихудший случай, а отслеживание задач не-RT, дающее непредсказуемый результат, будет переписывать наихудшую задержку для задач RT (это легко увидеть при запуске трассировщика wakeup).

Поскольку этот трассировщик работает только с задачами RT, воспользуемся для него вместо привычной команды ls командой sleep 1 в chrt, где меняется приоритет задаси.

  # echo 0 > options/function-trace
  # echo wakeup_rt > current_tracer
  # echo 1 > tracing_on
  # echo 0 > tracing_max_latency
  # chrt -f 5 sleep 1
  # echo 0 > tracing_on
  # cat trace
  # tracer: wakeup
  #
  # tracer: wakeup_rt
  #
  # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
  #    -----------------
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
    <idle>-0       3d.h4    0us :      0:120:R   + [003]  2389: 94:R sleep
    <idle>-0       3d.h4    1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
    <idle>-0       3d..3    5us : __schedule <-schedule
    <idle>-0       3d..3    5us :      0:120:R ==> [003]  2389: 94:R sleep

Запустив это в режиме ожидания, видим, что для переключения задачи потребовалось лишь 5 мксек. Отметим, что трассировка была остановлена к моменту, когда записываемая задача была запланирована, поскольку точка трассировки в планировании расположена перед фактическим переключателем (switch). Это можно изменить, добавив новый маркер в конце планировщика.

Отметим, что записываемая задача «спит» (sleep) с PID = 2389 и имеет rt_prio = 5. Этот приоритет относится к пользовательскому пространству, а не к ядру. Для SCHED_FIFO используется правило 1, для SCHED_RR — 2.

Отметим, что данные трассировки показывают внутренний приоритет (99 — rt_prio).

  <idle>-0       3d..3    5us :      0:120:R ==> [003]  2389: 94:R sleep

Запись 0:120:R означает бездействие с приоритетом nice = 0 (120 — 120), в рабочем состоянии (R). Спящая задача запланирована с 2389: 94:R. Т. е. приоритет является приоритетом ядра rt_prio (99 — 5 = 94) и задача также выполняется.

Повторим это с chrt -r 5 и установленной опцией function-trace.

  echo 1 > options/function-trace

  # tracer: wakeup_rt
  #
  # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
  #    -----------------
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
    <idle>-0       3d.h4    1us+:      0:120:R   + [003]  2448: 94:R sleep
    <idle>-0       3d.h4    2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
    <idle>-0       3d.h3    3us : check_preempt_curr <-ttwu_do_wakeup
    <idle>-0       3d.h3    3us : resched_curr <-check_preempt_curr
    <idle>-0       3dNh3    4us : task_woken_rt <-ttwu_do_wakeup
    <idle>-0       3dNh3    4us : _raw_spin_unlock <-try_to_wake_up
    <idle>-0       3dNh3    4us : sub_preempt_count <-_raw_spin_unlock
    <idle>-0       3dNh2    5us : ttwu_stat <-try_to_wake_up
    <idle>-0       3dNh2    5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
    <idle>-0       3dNh2    6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
    <idle>-0       3dNh1    6us : _raw_spin_lock <-__run_hrtimer
    <idle>-0       3dNh1    6us : add_preempt_count <-_raw_spin_lock
    <idle>-0       3dNh2    7us : _raw_spin_unlock <-hrtimer_interrupt
    <idle>-0       3dNh2    7us : sub_preempt_count <-_raw_spin_unlock
    <idle>-0       3dNh1    7us : tick_program_event <-hrtimer_interrupt
    <idle>-0       3dNh1    7us : clockevents_program_event <-tick_program_event
    <idle>-0       3dNh1    8us : ktime_get <-clockevents_program_event
    <idle>-0       3dNh1    8us : lapic_next_event <-clockevents_program_event
    <idle>-0       3dNh1    8us : irq_exit <-smp_apic_timer_interrupt
    <idle>-0       3dNh1    9us : sub_preempt_count <-irq_exit
    <idle>-0       3dN.2    9us : idle_cpu <-irq_exit
    <idle>-0       3dN.2    9us : rcu_irq_exit <-irq_exit
    <idle>-0       3dN.2   10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
    <idle>-0       3dN.2   10us : sub_preempt_count <-irq_exit
    <idle>-0       3.N.1   11us : rcu_idle_exit <-cpu_idle
    <idle>-0       3dN.1   11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
    <idle>-0       3.N.1   11us : tick_nohz_idle_exit <-cpu_idle
    <idle>-0       3dN.1   12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
    <idle>-0       3dN.1   12us : ktime_get <-tick_nohz_idle_exit
    <idle>-0       3dN.1   12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
    <idle>-0       3dN.1   13us : cpu_load_update_nohz <-tick_nohz_idle_exit
    <idle>-0       3dN.1   13us : _raw_spin_lock <-cpu_load_update_nohz
    <idle>-0       3dN.1   13us : add_preempt_count <-_raw_spin_lock
    <idle>-0       3dN.2   13us : __cpu_load_update <-cpu_load_update_nohz
    <idle>-0       3dN.2   14us : sched_avg_update <-__cpu_load_update
    <idle>-0       3dN.2   14us : _raw_spin_unlock <-cpu_load_update_nohz
    <idle>-0       3dN.2   14us : sub_preempt_count <-_raw_spin_unlock
    <idle>-0       3dN.1   15us : calc_load_nohz_stop <-tick_nohz_idle_exit
    <idle>-0       3dN.1   15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
    <idle>-0       3dN.1   15us : hrtimer_cancel <-tick_nohz_idle_exit
    <idle>-0       3dN.1   15us : hrtimer_try_to_cancel <-hrtimer_cancel
    <idle>-0       3dN.1   16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
    <idle>-0       3dN.1   16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
    <idle>-0       3dN.1   16us : add_preempt_count <-_raw_spin_lock_irqsave
    <idle>-0       3dN.2   17us : __remove_hrtimer <-remove_hrtimer.part.16
    <idle>-0       3dN.2   17us : hrtimer_force_reprogram <-__remove_hrtimer
    <idle>-0       3dN.2   17us : tick_program_event <-hrtimer_force_reprogram
    <idle>-0       3dN.2   18us : clockevents_program_event <-tick_program_event
    <idle>-0       3dN.2   18us : ktime_get <-clockevents_program_event
    <idle>-0       3dN.2   18us : lapic_next_event <-clockevents_program_event
    <idle>-0       3dN.2   19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
    <idle>-0       3dN.2   19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
    <idle>-0       3dN.1   19us : hrtimer_forward <-tick_nohz_idle_exit
    <idle>-0       3dN.1   20us : ktime_add_safe <-hrtimer_forward
    <idle>-0       3dN.1   20us : ktime_add_safe <-hrtimer_forward
    <idle>-0       3dN.1   20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
    <idle>-0       3dN.1   20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
    <idle>-0       3dN.1   21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
    <idle>-0       3dN.1   21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
    <idle>-0       3dN.1   21us : add_preempt_count <-_raw_spin_lock_irqsave
    <idle>-0       3dN.2   22us : ktime_add_safe <-__hrtimer_start_range_ns
    <idle>-0       3dN.2   22us : enqueue_hrtimer <-__hrtimer_start_range_ns
    <idle>-0       3dN.2   22us : tick_program_event <-__hrtimer_start_range_ns
    <idle>-0       3dN.2   23us : clockevents_program_event <-tick_program_event
    <idle>-0       3dN.2   23us : ktime_get <-clockevents_program_event
    <idle>-0       3dN.2   23us : lapic_next_event <-clockevents_program_event
    <idle>-0       3dN.2   24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
    <idle>-0       3dN.2   24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
    <idle>-0       3dN.1   24us : account_idle_ticks <-tick_nohz_idle_exit
    <idle>-0       3dN.1   24us : account_idle_time <-account_idle_ticks
    <idle>-0       3.N.1   25us : sub_preempt_count <-cpu_idle
    <idle>-0       3.N..   25us : schedule <-cpu_idle
    <idle>-0       3.N..   25us : __schedule <-preempt_schedule
    <idle>-0       3.N..   26us : add_preempt_count <-__schedule
    <idle>-0       3.N.1   26us : rcu_note_context_switch <-__schedule
    <idle>-0       3.N.1   26us : rcu_sched_qs <-rcu_note_context_switch
    <idle>-0       3dN.1   27us : rcu_preempt_qs <-rcu_note_context_switch
    <idle>-0       3.N.1   27us : _raw_spin_lock_irq <-__schedule
    <idle>-0       3dN.1   27us : add_preempt_count <-_raw_spin_lock_irq
    <idle>-0       3dN.2   28us : put_prev_task_idle <-__schedule
    <idle>-0       3dN.2   28us : pick_next_task_stop <-pick_next_task
    <idle>-0       3dN.2   28us : pick_next_task_rt <-pick_next_task
    <idle>-0       3dN.2   29us : dequeue_pushable_task <-pick_next_task_rt
    <idle>-0       3d..3   29us : __schedule <-preempt_schedule
    <idle>-0       3d..3   30us :      0:120:R ==> [003]  2448: 94:R sleep

Трек даже при отслеживании функций не слишком велик и приведен здесь полностью.

Прерывание произошло в момент бездействия системы. Где-то перед вызовом task_woken_rt() был установлен флаг NEED_RESCHED, что показано первым включением символа N.

Трассировка задержки и события

Трассировка функций может вносить значительные задержки, но без нее трудно установить причины задержки. Золотой серединой является включение трассировки событий, как показано ниже.

  # echo 0 > options/function-trace
  # echo wakeup_rt > current_tracer
  # echo 1 > events/enable
  # echo 1 > tracing_on
  # echo 0 > tracing_max_latency
  # chrt -f 5 sleep 1
  # echo 0 > tracing_on
  # cat trace
  # tracer: wakeup_rt
  #
  # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
  # --------------------------------------------------------------------
  # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
  #    -----------------
  #
  #                  _------=> CPU#            
  #                 / _-----=> irqs-off        
  #                | / _----=> need-resched    
  #                || / _---=> hardirq/softirq 
  #                ||| / _--=> preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
    <idle>-0       2d.h4    0us :      0:120:R   + [002]  5882: 94:R sleep
    <idle>-0       2d.h4    0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
    <idle>-0       2d.h4    1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
    <idle>-0       2dNh2    1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
    <idle>-0       2.N.2    2us : power_end: cpu_id=2
    <idle>-0       2.N.2    3us : cpu_idle: state=4294967295 cpu_id=2
    <idle>-0       2dN.3    4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
    <idle>-0       2dN.3    4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer expires=34311211000000 softexpires=34311211000000
    <idle>-0       2.N.2    5us : rcu_utilization: Start context switch
    <idle>-0       2.N.2    5us : rcu_utilization: End context switch
    <idle>-0       2d..3    6us : __schedule <-schedule
    <idle>-0       2d..3    6us :      0:120:R ==> [002]  5882: 94:R sleep

Определение аппаратной задержки

Для определения задержек в оборудовании служит трассировщик hwlat. Следует отметить, что этот трассировщик влияет на производительность всей системы и может полностью загружать CPU с запретом прерываний.

  # echo hwlat > current_tracer
  # sleep 100
  # cat trace
  # tracer: hwlat
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |
             <...>-3638  [001] d... 19452.055471: #1     inner/outer(us):   12/14    ts:1499801089.066141940
             <...>-3638  [003] d... 19454.071354: #2     inner/outer(us):   11/9     ts:1499801091.082164365
             <...>-3638  [002] dn.. 19461.126852: #3     inner/outer(us):   12/9     ts:1499801098.138150062
             <...>-3638  [001] d... 19488.340960: #4     inner/outer(us):    8/12    ts:1499801125.354139633
             <...>-3638  [003] d... 19494.388553: #5     inner/outer(us):    8/12    ts:1499801131.402150961
             <...>-3638  [003] d... 19501.283419: #6     inner/outer(us):    0/12    ts:1499801138.297435289 nmi-total:4 nmi-count:1

Приведенный выше вывод содержит заголовок с описанием формата. Для всех событий прерывания запрещены (d). Вывод в колонке FUNCTION описан ниже.

#1

Число записанных событий, превышающих tracing_threshold (см. ниже).

inner/outer(us): 12/14

Два значения, показывающие внутреннюю (inner) и внешнюю (outer) задержку. Тест выполняется в цикле, проверяя временную метку дважды. Задержка между двумя метками одного цикла называется внутренней, а задержка между меткой предыдущего и текущего циклов — внешней.

ts:1499801089.066141940

Метка абсолютного времени события.

nmi-total:4 nmi-count:1

Для поддерживающей немаскируемые прерывания архитектуры при NMI в процессе тестирования время, проведенное в NMI, указывается в поле nmi-total (мксек).

Если архитектура поддерживает NMI, поле nmi-count будет показывать число NMI в процессе тестирования.

Файлы hwlat

tracing_thresh

Если в этом файле указано значение 0, автоматически устанавливается значение 10 (мксек), определяющее порог задержки, которая вызывает запись трассировки в кольцевой буфер.

Отметим, что по завершении трассировщика hwlat (записи другого трассировщика в current_tracer) в файле восстанавливается исходное значение tracing_threshold.

hwlat_detector/width

Продолжительность работы теста с отключенными прерываниями.

hwlat_detector/window

Продолжительность окна тестирования — тест выполнялся в течение width мксек в течение window мксек.

tracing_cpumask

При запуске теста создается поток (thread) ядра для работы теста. Этот поток будет передаваться между CPU, указанными в tracing_cpumask каждый интервал (окно — window). Для работы теста на определенных CPU в этом файле устанавливается нужная маска.

Трассировщик function

Этот трассировщик отслеживает функции. Включить трассировщик можно через файловую систему debugfs. Следует убедиться, что установлена переменная (файл) ftrace_enabled, поскольку в противном случае трассировка не будет делать ничего (см. ftrace_enabled ниже).

Ниже приведен пример команд и вывода при трассировке функций.

  # sysctl kernel.ftrace_enabled=1
  # echo function > current_tracer
  # echo 1 > tracing_on
  # usleep 1
  # echo 0 > tracing_on
  # cat trace
  # tracer: function
  #
  # entries-in-buffer/entries-written: 24799/24799   #P:4
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |
              bash-1994  [002] ....  3082.063030: mutex_unlock <-rb_simple_write
              bash-1994  [002] ....  3082.063031: __mutex_unlock_slowpath <-mutex_unlock
              bash-1994  [002] ....  3082.063031: __fsnotify_parent <-fsnotify_modify
              bash-1994  [002] ....  3082.063032: fsnotify <-fsnotify_modify
              bash-1994  [002] ....  3082.063032: __srcu_read_lock <-fsnotify
              bash-1994  [002] ....  3082.063032: add_preempt_count <-__srcu_read_lock
              bash-1994  [002] ...1  3082.063032: sub_preempt_count <-__srcu_read_lock
              bash-1994  [002] ....  3082.063033: __srcu_read_unlock <-fsnotify

Примечание. Трассировщик функций использует кольцевые буферы для хранения показанных выше записей и новые данные могут переписывать более старые. Иногда использования команды echo не достаточно для прекращения трассировки, поскольку данные могут быть перезаписаны. По этой причине иногда лучше отключать трассировку из программы. Это позволит остановить трассировку в нужной точке. Для выключения трассировки непосредственно из программы на языке C можно воспользоваться кодом, подобным приведенному ниже.

	int trace_fd;
	[...]
	int main(int argc, char *argv[]) {
		[...]
		trace_fd = open(tracing_file("tracing_on"), O_WRONLY);
		[...]
		if (condition_hit()) {
			write(trace_fd, "0", 1);
		}
		[...]
	}

Трассировка одного потока

Путем записи нужного значения в файл set_ftrace_pid можно ограничиться отслеживанием одного потока (thread).

  # cat set_ftrace_pid
  no pid
  # echo 3111 > set_ftrace_pid
  # cat set_ftrace_pid
  3111
  # echo function > current_tracer
  # cat trace | head
  # tracer: function
  #
  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
  #              | |       |          |         |
      yum-updatesd-3111  [003]  1637.254676: finish_task_switch <-thread_return
      yum-updatesd-3111  [003]  1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
      yum-updatesd-3111  [003]  1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
      yum-updatesd-3111  [003]  1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
      yum-updatesd-3111  [003]  1637.254685: fget_light <-do_sys_poll
      yum-updatesd-3111  [003]  1637.254686: pipe_poll <-do_sys_poll
  # echo > set_ftrace_pid
  # cat trace |head
  # tracer: function
  #
  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
  #              | |       |          |         |
  ##### CPU 3 buffer started ####
      yum-updatesd-3111  [003]  1701.957688: free_poll_entry <-poll_freewait
      yum-updatesd-3111  [003]  1701.957689: remove_wait_queue <-free_poll_entry
      yum-updatesd-3111  [003]  1701.957691: fput <-free_poll_entry
      yum-updatesd-3111  [003]  1701.957692: audit_syscall_exit <-sysret_audit
      yum-updatesd-3111  [003]  1701.957693: path_put <-audit_syscall_exit

Если нужно отслеживать функцию при выполнении, можно воспользоваться чем-то вроде приведенной программы.

	#include <stdio.h>
	#include <stdlib.h>
	#include <sys/types.h>
	#include <sys/stat.h>
	#include <fcntl.h>
	#include <unistd.h>
	#include <string.h>

	#define _STR(x) #x
	#define STR(x) _STR(x)
	#define MAX_PATH 256

	const char *find_tracefs(void)
	{
	       static char tracefs[MAX_PATH+1];
	       static int tracefs_found;
	       char type[100];
	       FILE *fp;

	       if (tracefs_found)
		       return tracefs;

	       if ((fp = fopen("/proc/mounts","r")) == NULL) {
		       perror("/proc/mounts");
		       return NULL;
	       }

	       while (fscanf(fp, "%*s %"
		             STR(MAX_PATH)
		             "s %99s %*s %*d %*d\n",
		             tracefs, type) == 2) {
		       if (strcmp(type, "tracefs") == 0)
		               break;
	       }
	       fclose(fp);

	       if (strcmp(type, "tracefs") != 0) {
		       fprintf(stderr, "tracefs not mounted");
		       return NULL;
	       }

	       strcat(tracefs, "/tracing/");
	       tracefs_found = 1;

	       return tracefs;
	}

	const char *tracing_file(const char *file_name)
	{
	       static char trace_file[MAX_PATH+1];
	       snprintf(trace_file, MAX_PATH, "%s/%s", find_tracefs(), file_name);
	       return trace_file;
	}

	int main (int argc, char **argv)
	{
		if (argc < 1)
		        exit(-1);

		if (fork() > 0) {
		        int fd, ffd;
		        char line[64];
		        int s;

		        ffd = open(tracing_file("current_tracer"), O_WRONLY);
		        if (ffd < 0)
		                exit(-1);
		        write(ffd, "nop", 3);

		        fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
		        s = sprintf(line, "%d\n", getpid());
		        write(fd, line, s);

		        write(ffd, "function", 8);

		        close(fd);
		        close(ffd);

		        execvp(argv[1], argv+1);
		}

		return 0;
	}

Подойдет также простой сценарий, показанный ниже.

  #!/bin/bash

  tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
  echo nop > $tracefs/tracing/current_tracer
  echo 0 > $tracefs/tracing/tracing_on
  echo $$ > $tracefs/tracing/set_ftrace_pid
  echo function > $tracefs/tracing/current_tracer
  echo 1 > $tracefs/tracing/tracing_on
  exec "$@"

Трассировщик function_graph

Этот трассировщик похож на function, но проверяет функции на входе и выходе. Это делается с помощью динамически выделяемого стека адресов возврата в каждой task_struct. На входе функции трассировщик переписывает адрес возврата каждой отслеживаемой функции для установки специального «зонда». Исходный адрес возврата сохраняется в стеке возврата структуры task_struct.

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

Этот трассировщик полезен в нескольких ситуациях:

  • поиск причин странного поведения ядра;

  • обнаружение непонятных задержек;

  • быстрый поиск пути выполнение определенной функции;

  • исследование происходящего внутри ядра.

  # tracer: function_graph
  #
  # CPU  DURATION                  FUNCTION CALLS
  # |     |   |                     |   |   |   |

   0)               |  sys_open() {
   0)               |    do_sys_open() {
   0)               |      getname() {
   0)               |        kmem_cache_alloc() {
   0)   1.382 us    |          __might_sleep();
   0)   2.478 us    |        }
   0)               |        strncpy_from_user() {
   0)               |          might_fault() {
   0)   1.389 us    |            __might_sleep();
   0)   2.553 us    |          }
   0)   3.807 us    |        }
   0)   7.876 us    |      }
   0)               |      alloc_fd() {
   0)   0.668 us    |        _spin_lock();
   0)   0.570 us    |        expand_files();
   0)   0.586 us    |        _spin_unlock();

Здесь имеется несколько колонок, которые можно динамически включать и выключать. Можно использовать любую подходящую комбинацию опций.

  • Номер процессора, на котором выполняется функция, по умолчанию выводится. Иногда может потребоваться отслеживание лишь одного процессора (см. файл tracing_cpu_mask) или отслеживать функции без привязки к процессорам.

    • Скрыть номер процессора — echo nofuncgraph-cpu > trace_options.

    • Показывать номер процессора — echo funcgraph-cpu > trace_options.

  • Продолжительность выполнения функции указывается после закрывающей (фигурной) скобки функции или в одной строке с функцией, если эта функция не делает других вызовов. По умолчнию отображение продолжительности включено.

    • Скрыть продолжительность вызова — echo nofuncgraph-duration > trace_options.

    • Показывать продолжительность вызова — echo funcgraph-duration > trace_options.

  • Поле служебных данных (overhead) указывается перед полем продолжительности в случае достижения порога длительности.

    • Скрыть служебные данные — echo nofuncgraph-overhead > trace_options.

    • Показывать служебные данные — echo funcgraph-overhead > trace_options

    3) # 1837.709 us |          } /* __switch_to */
    3)               |          finish_task_switch() {
    3)   0.313 us    |            _raw_spin_unlock_irq();
    3)   3.177 us    |          }
    3) # 1889.063 us |        } /* __schedule */
    3) ! 140.417 us  |      } /* __schedule */
    3) # 2034.948 us |    } /* schedule */
    3) * 33998.59 us |  } /* schedule_preempt_disabled */

    [...]

    1)   0.260 us    |              msecs_to_jiffies();
    1)   0.313 us    |              __rcu_read_unlock();
    1) + 61.770 us   |            }
    1) + 64.479 us   |          }
    1)   0.313 us    |          rcu_bh_qs();
    1)   0.313 us    |          __local_bh_enable();
    1) ! 217.240 us  |        }
    1)   0.365 us    |        idle_cpu();
    1)               |        rcu_irq_exit() {
    1)   0.417 us    |          rcu_eqs_enter_common.isra.47();
    1)   3.125 us    |        }
    1) ! 227.812 us  |      }
    1) ! 457.395 us  |    }
    1) @ 119760.2 us |  }

    [...]

    2)               |    handle_IPI() {
    1)   6.979 us    |                  }
    2)   0.417 us    |      scheduler_ipi();
    1)   9.791 us    |                }
    1) + 12.917 us   |              }
    2)   3.490 us    |    }
    1) + 15.729 us   |            }
    1) + 18.542 us   |          }
    2) $ 3594274 us  |  }

Маркеры продолжительности

+ — больше 10 мксек.

! — больше 100 мксек.

# — больше 1000 мксек.

* — больше 10 мсек.

@ — больше 100 мсек.

$ — больше 1 сек.

  • Поле task/pid показывает строку команды и pid процесса, в котором функция выполняется. По умолчанию это поле не выводится.

    • Скрыть поле — echo nofuncgraph-proc > trace_options.

    • Показывать поле — echo funcgraph-proc > trace_options.

    # tracer: function_graph
    #
    # CPU  TASK/PID        DURATION                  FUNCTION CALLS
    # |    |    |           |   |                     |   |   |   |
    0)    sh-4802     |               |                  d_free() {
    0)    sh-4802     |               |                    call_rcu() {
    0)    sh-4802     |               |                      __call_rcu() {
    0)    sh-4802     |   0.616 us    |                        rcu_process_gp_end();
    0)    sh-4802     |   0.586 us    |                        check_for_new_grace_period();
    0)    sh-4802     |   2.899 us    |                      }
    0)    sh-4802     |   4.040 us    |                    }
    0)    sh-4802     |   5.151 us    |                  }
    0)    sh-4802     | + 49.370 us   |                }
  • Поле «абсолютного» времени содержит временную метку системных часов, отсчитываемую от момента загрузки системы. Время указывается на входе и выходе функции.

    • Скрыть время — echo nofuncgraph-abstime > trace_options

    • Показывать время — echo funcgraph-abstime > trace_options

    #
    #      TIME       CPU  DURATION                  FUNCTION CALLS
    #       |         |     |   |                     |   |   |   |
    360.774522 |   1)   0.541 us    |                                          }
    360.774522 |   1)   4.663 us    |                                        }
    360.774523 |   1)   0.541 us    |                                        __wake_up_bit();
    360.774524 |   1)   6.796 us    |                                      }
    360.774524 |   1)   7.952 us    |                                    }
    360.774525 |   1)   9.063 us    |                                  }
    360.774525 |   1)   0.615 us    |                                  journal_mark_dirty();
    360.774527 |   1)   0.578 us    |                                  __brelse();
    360.774528 |   1)               |                                  reiserfs_prepare_for_journal() {
    360.774528 |   1)               |                                    unlock_buffer() {
    360.774529 |   1)               |                                      wake_up_bit() {
    360.774529 |   1)               |                                        bit_waitqueue() {
    360.774530 |   1)   0.594 us    |                                          __phys_addr();

Имя функции, начало которой не попадает в буфер трассировки выводится после закрывающей скобки для функции. Вывод этого имени можно включить для упрощения поиска продолжительности функций с помощью grep. По умолчанию вывод отключен

  • Скрыть имя — echo nofuncgraph-tail > trace_options.

  • Показывать имя — echo funcgraph-tail > trace_options.

Пример без вывода имен (nofuncgraph-tail), как принято по умолчанию.

    0)               |      putname() {
    0)               |        kmem_cache_free() {
    0)   0.518 us    |          __phys_addr();
    0)   1.757 us    |        }
    0)   2.861 us    |      }

Пример с выводом имен (funcgraph-tail)

    0)               |      putname() {
    0)               |        kmem_cache_free() {
    0)   0.518 us    |          __phys_addr();
    0)   1.757 us    |        } /* kmem_cache_free() */
    0)   2.861 us    |      } /* putname() */

Можно добавить комментарии к конкретным функциям с помощью trace_printk(). Например, для включения комментариев в функцию __might_sleep() достаточно включить файл <linux/ftrace.h> и вызвать trace_printk() внутри __might_sleep(). Например,

	trace_printk("I'm a comment!\n")

будет давать вывод

   1)               |             __might_sleep() {
   1)               |                /* I'm a comment! */
   1)   1.449 us    |             }

Другие варианты применения этого трассировщика описаны в следующем разделе.


Динамическая трассировка ftrace

Если установлена опция ядра CONFIG_DYNAMIC_FTRACE, система будет работать почти без связанных с трассировкой издержек при отключенной трассировке функций. Это работает за счет вызова функции mcount (помещается в начале каждой функции ядра с помощью опции -pg компилятора gcc6), указывающей простой возврат.

При компиляции каждый объект файла C запускается через программу recordmcount (находится в каталоге scripts), котоая анализирует заголовки ELF в объекте C для поиска всех вызовов в разделе .text, вызывающих функцию mcount7.

Отметим, что отслеживаются не все разделы — трассировка может быть отключена notrace или заблокирована иным путем и все встроенные функции не будут отслеживаться. Для просмотра списка функций, которые могут трассироваться, следует обратиться к файлу available_filter_functions.

Создается раздел __mcount_loc, в котором содержатся ссылки на все вызовы mcount/fentry в разделе .text. Программа recordmcount заново связывает этот раздел с исходными объектами. На этапе финальной компоновки ядра все эти ссылки будут добавлены в одну таблицу.

При загрузке (до инициализации SMP) динамический код ftrace сканирует эту таблицу и заменяет все найденные ссылки на nop, а также записывает местоположения, добавленные в список available_filter_functions. Модули обрабатываются по мере их загрузки до начала выполнения. При выгрузке модуля реализованные в нем функции удаляются из списка функций ftrace. Эту процедуру автоматически выполняет код выгрузки модулей и автор модуля не должен беспокоиться об этом.

При включенной трассировке процесс изменения точек трассировки функций зависит от архитектуры. Старый метод использовал kstop_machine для предотвращения «гонок» CPU, выполняющих измененный код (что может заставлять CPU делать нежелательные вещи, особенно в тех случаях, когда измененный код пересекает границу кэше или страницы) и операции nop обратно помещались в вызовы. Но сейчас вместо mcount (сейчас это просто функция-заглушка) используются вызовы инфраструктуры ftrace.

Новый метод изменения точек трассировки функций заключается в размещении точки остановки (breakpoint) в изменяемом месте, синхронизации всех CPU, и изменении остальной части инструкции, не охваченной точкой остановки. CPU синхронизируются еще раз и точка установки удаляется из окончательной версии.

Некоторым вариантам архитектуры не нужно заботиться о синхронизации, они просто могут поместить новый код взамен прежнего без возникновения проблем с другими CPU, работающими в это же время.

Одним из побочных эффектов записи функций, которые будут отслеживаться, является то, что можно выбрать функции, которые мы хотим трассировать, и функции, для которых хотим, чтобы вызовы mcount оставались nop.

Используется два файла, один из которых служит для разрешения, другой для запрета трассировки заданных функций

  set_ftrace_filter

и

  set_ftrace_notrace

Список функций, которые можно включить в эти файлы содержится в файле available_filter_functions.

  # cat available_filter_functions
  put_prev_task_idle
  kmem_cache_create
  pick_next_task_rt
  get_online_cpus
  pick_next_task_fair
  mutex_lock
  [...]

Если интересно отслеживать лишь sys_nanosleep и hrtimer_interrupt, можно воспользоваться приведенными ниже командами.

  # echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter
  # echo function > current_tracer
  # echo 1 > tracing_on
  # usleep 1
  # echo 0 > tracing_on
  # cat trace
  # tracer: function
  #
  # entries-in-buffer/entries-written: 5/5   #P:4
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |
            usleep-2665  [001] ....  4186.475355: sys_nanosleep <-system_call_fastpath
            <idle>-0     [001] d.h1  4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
            usleep-2665  [001] d.h1  4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
            <idle>-0     [003] d.h1  4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
            <idle>-0     [002] d.h1  4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt

Для просмотра функций, которые будут отслеживаться, можно воспользоваться командой

  # cat set_ftrace_filter
  hrtimer_interrupt
  sys_nanosleep

Иногда явного указания имен всех функций не достаточно, поэтому фильтры поддерживают шаблоны сопоставлений (см. glob).

match*

соответствует всем функциям, начинающимся с match.

*match

соответствует всем функциям, заканчивающимся match.

*match*

соответствует всем функциям, содержащим match в имени.

match1*match2

соответствует всем функциям, начинающимся с match1 и заканчивающимися match2.

Примечание. Шаблоны сопоставления лучше указывать в кавычках, поскольку в противном случае интерпретатор команд может счесть параметры именами файлов в локальном каталоге.

Например,

  # echo 'hrtimer_*' > set_ftrace_filter

Приведет к выводу, показанному ниже

  # tracer: function
  #
  # entries-in-buffer/entries-written: 897/897   #P:4
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |
            <idle>-0     [003] dN.1  4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
            <idle>-0     [003] dN.1  4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
            <idle>-0     [003] dN.2  4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
            <idle>-0     [003] dN.1  4228.547805: hrtimer_forward <-tick_nohz_idle_exit
            <idle>-0     [003] dN.1  4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
            <idle>-0     [003] d..1  4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
            <idle>-0     [003] d..1  4228.547859: hrtimer_start <-__tick_nohz_idle_enter
            <idle>-0     [003] d..2  4228.547860: hrtimer_force_reprogram <-__rem

Отметим, что трассировка sys_nanosleep была потеряна.

  # cat set_ftrace_filter
  hrtimer_run_queues
  hrtimer_run_pending
  hrtimer_init
  hrtimer_cancel
  hrtimer_try_to_cancel
  hrtimer_forward
  hrtimer_start
  hrtimer_reprogram
  hrtimer_force_reprogram
  hrtimer_get_next_event
  hrtimer_interrupt
  hrtimer_nanosleep
  hrtimer_wakeup
  hrtimer_get_remaining
  hrtimer_get_res
  hrtimer_init_sleeper

Причиной этого стало указание символа > в команде echo. Одиночная угловая скобка (>) задает переписывание файла, а два символа (>>) указывают добавление в конец файла.

Для сброса фильтров с восстановлением записи всех функций можно воспользоваться командой

 # echo > set_ftrace_filter
 # cat set_ftrace_filter
 #

Далее показано, как можно добавить фильтры, не удаляя имеющихся.

  # echo sys_nanosleep > set_ftrace_filter
  # cat set_ftrace_filter
  sys_nanosleep
  # echo 'hrtimer_*' >> set_ftrace_filter
  # cat set_ftrace_filter
  hrtimer_run_queues
  hrtimer_run_pending
  hrtimer_init
  hrtimer_cancel
  hrtimer_try_to_cancel
  hrtimer_forward
  hrtimer_start
  hrtimer_reprogram
  hrtimer_force_reprogram
  hrtimer_get_next_event
  hrtimer_interrupt
  sys_nanosleep
  hrtimer_nanosleep
  hrtimer_wakeup
  hrtimer_get_remaining
  hrtimer_get_res
  hrtimer_init_sleeper

Фильтр set_ftrace_notrace исключает трассировку указанных в файле функций. Например, команда

  # echo '*preempt*' '*lock*' > set_ftrace_notrace

Приведет к показанному ниже результату.

  # tracer: function
  #
  # entries-in-buffer/entries-written: 39608/39608   #P:4
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |
              bash-1994  [000] ....  4342.324896: file_ra_state_init <-do_dentry_open
              bash-1994  [000] ....  4342.324897: open_check_o_direct <-do_last
              bash-1994  [000] ....  4342.324897: ima_file_check <-do_last
              bash-1994  [000] ....  4342.324898: process_measurement <-ima_file_check
              bash-1994  [000] ....  4342.324898: ima_get_action <-process_measurement
              bash-1994  [000] ....  4342.324898: ima_match_policy <-ima_get_action
              bash-1994  [000] ....  4342.324899: do_truncate <-do_last
              bash-1994  [000] ....  4342.324899: should_remove_suid <-do_truncate
              bash-1994  [000] ....  4342.324899: notify_change <-do_truncate
              bash-1994  [000] ....  4342.324900: current_fs_time <-notify_change
              bash-1994  [000] ....  4342.324900: current_kernel_time <-current_fs_time
              bash-1994  [000] ....  4342.324900: timespec_trunc <-current_fs_time

Откуда можно видеть, что отслеживания lock и preempt не происходит.

Динамическая трассировка с function_graph

Хотя приведенные выше разъяснения относятся к обоим трассировщикам function и function_graph, последний имеет некоторые особые возможности.

Если вы хотите отслеживать лишь одну функцию и всех ее потомком, достаточно включить имя этой функции с помощью команды echo в файл set_graph_function. Например,

 echo __do_fault > set_graph_function

будет выводить «расширенную» трассировку функции __do_fault().

   0)               |  __do_fault() {
   0)               |    filemap_fault() {
   0)               |      find_lock_page() {
   0)   0.804 us    |        find_get_page();
   0)               |        __might_sleep() {
   0)   1.329 us    |        }
   0)   3.904 us    |      }
   0)   4.979 us    |    }
   0)   0.653 us    |    _spin_lock();
   0)   0.578 us    |    page_add_file_rmap();
   0)   0.525 us    |    native_set_pte_at();
   0)   0.585 us    |    _spin_unlock();
   0)               |    unlock_page() {
   0)   0.541 us    |      page_waitqueue();
   0)   0.639 us    |      __wake_up_bit();
   0)   2.786 us    |    }
   0) + 14.237 us   |  }
   0)               |  __do_fault() {
   0)               |    filemap_fault() {
   0)               |      find_lock_page() {
   0)   0.698 us    |        find_get_page();
   0)               |        __might_sleep() {
   0)   1.412 us    |        }
   0)   3.950 us    |      }
   0)   5.098 us    |    }
   0)   0.631 us    |    _spin_lock();
   0)   0.571 us    |    page_add_file_rmap();
   0)   0.526 us    |    native_set_pte_at();
   0)   0.586 us    |    _spin_unlock();
   0)               |    unlock_page() {
   0)   0.533 us    |      page_waitqueue();
   0)   0.638 us    |      __wake_up_bit();
   0)   2.793 us    |    }
   0) + 14.012 us   |  }

Можно таким способом отслеживать несколько функций, например,

 echo sys_open > set_graph_function
 echo sys_close >> set_graph_function

Если после этого нужно вернуться к отслеживанию всех функций, можно сбросить фильтр командой

 echo > set_graph_function

ftrace_enabled

Следует отметить, что sysctl ftrace_enable служит основным выключателем для трассировщика функций, который по умолчанию включен (если трассировка функций активизирована в ядре). При отключении трассировки выключается отслеживание всех функций (не только трассировщики функций для ftrace, но и другие — perf, kprobe, трассировка стека, профилирование и т. п.). Следует осторожно относиться к запрету трассировки. Команды управления приведены ниже.

  sysctl kernel.ftrace_enabled=0
  sysctl kernel.ftrace_enabled=1

или

  echo 0 > /proc/sys/kernel/ftrace_enabled
  echo 1 > /proc/sys/kernel/ftrace_enabled

Команды фильтрации

Интерфейс set_ftrace_filter поддерживает несколько команд, имеющих формат

  <function>:<command>:<parameter>

Ниже перечислены поддерживаемые команды.

mod

Включает фильтрацию функций на уровне модуля, задаваемого параметром. Например, если нужно отслеживать лишь функции write* в модуле ext3, можно воспользоваться командой

   echo 'write*:mod:ext3' > set_ftrace_filter

Эта команда взаимодействует с фильтрами так же, как для фильтрации по именам функций, т. е. для добавления других функций применяется операция записи в конец файла (>>). Для удалении функции применяется восклицательный знак перед именем.

   echo '!writeback*:mod:ext3' >> set_ftrace_filter

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

   echo '!*:mod:!ext3' >> set_ftrace_filter

Для запрета трассировки всех модулей с сохранением трассировки ядра служит команд

   echo '!*:mod:*' >> set_ftrace_filter

Для фильтрации только функций ядра служат команды вида

   echo '*write*:mod:!*' >> set_ftrace_filter

Для фильтрации набора модулей служат команды вида

   echo '*write*:mod:*snd*' >> set_ftrace_filter

traceon/traceoff

Эти команды включают и выключают трассировку только при обращении к указанным функциям. Параметр определяет число включений и отключений трассировки, при отсутствии параметра число не ограничивается. Например, для запрета трассировки при первых 5 вызовах __schedule_bug можно воспользоваться командой

   echo '__schedule_bug:traceoff:5' > set_ftrace_filter

Для запрета трассировки при вызове __schedule_bug служит команда

   echo '__schedule_bug:traceoff' > set_ftrace_filter

Эти команды являются накопительными независимо от их добавления в set_ftrace_filter. Для удаления команды указывается символ ! Перед ее именем и значение 0 для параметра

   echo '!__schedule_bug:traceoff:0' > set_ftrace_filter

Приведенная выше команда удаляет traceoff для функции __schedule_bug со счетчиком. Для удаления команд бкз счтечиков можно воспользоваться командой вида

   echo '!__schedule_bug:traceoff' > set_ftrace_filter

snapshot

Будет вызывать создание моментального снимка (snapshot) при вызове указанной функции.

   echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter

Для однократного создания снимка служат команды вида

   echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter

Для удаления приведенных выше команд можно воспользоваться командами

   echo '!native_flush_tlb_others:snapshot' > set_ftrace_filter
   echo '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter

enable_event/disable_event

Эти команды могут включать и выключать трассировку событий. Отметим, что по причине «чувствительности» обратных вызовов трассировки функций при использовании этих команд точки трассировки активируются, но отключаются они в «мягком» (soft) режиме, т. е. точка трассировки будет вызываться, просто не будет отслеживаться ничего. Точка трассировки события остается в таком режиме, пока есть использующие ее команды.

   echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > set_ftrace_filter

Формат команд показан ниже.

    <function>:enable_event:<system>:<event>[:count]
    <function>:disable_event:<system>:<event>[:count]

Для удаления связанных с событиями команд служат приведенные ниже команды

   echo '!try_to_wake_up:enable_event:sched:sched_switch:0' > set_ftrace_filter
   echo '!schedule:disable_event:sched:sched_switch' > set_ftrace_filter

dump

При обращении к функции на консоль будет выводиться содержимое кольцевого буфера ftrace. Это полезно при отладке, когда вы хотите быстро увидеть трассировку при обращении к некой функции. Например, ее можно использовать для просмотра буфера перед повторяющимся отказом.

cpudump

При обращении к функции на консоль будет выводиться содержимое кольцевого буфера ftrace для текущего CPU. В отличие от команды dump выводиться будет лишь буфер CPU, на котором выполняется вызвавшая вывод функция.

trace_pipe

Файл trace_pipe выводит те же данные, что и trace, но влияние на трассировку различается. Каждая запись из trace_pipe «потребляется» при считывании, т. е. последовательные операции чтения будут давать новый результат.

  # echo function > current_tracer
  # cat trace_pipe > /tmp/trace.out &
  [1] 4153
  # echo 1 > tracing_on
  # usleep 1
  # echo 0 > tracing_on
  # cat trace
  # tracer: function
  #
  # entries-in-buffer/entries-written: 0/0   #P:4
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |

  #
  # cat /tmp/trace.out
             bash-1994  [000] ....  5281.568961: mutex_unlock <-rb_simple_write
             bash-1994  [000] ....  5281.568963: __mutex_unlock_slowpath <-mutex_unlock
             bash-1994  [000] ....  5281.568963: __fsnotify_parent <-fsnotify_modify
             bash-1994  [000] ....  5281.568964: fsnotify <-fsnotify_modify
             bash-1994  [000] ....  5281.568964: __srcu_read_lock <-fsnotify
             bash-1994  [000] ....  5281.568964: add_preempt_count <-__srcu_read_lock
             bash-1994  [000] ...1  5281.568965: sub_preempt_count <-__srcu_read_lock
             bash-1994  [000] ....  5281.568965: __srcu_read_unlock <-fsnotify
             bash-1994  [000] ....  5281.568967: sys_dup2 <-system_call_fastpath

Отметим, что чтение файла trace_pipe будет блокироваться, пока в него не добавлено новых данных.

Записи трассировки

При диагностике проблем в ядре избыток или недостаток данных могут создавать проблемы. Фалй buffer_size_kb сшлужит для изменения размера внутренних буферов трассировки. Значение в файле указывает число записей, которые могут быть созданы для каждого CPU. Для определения полного размера это значение следует умножить на число процессоров.

  # cat buffer_size_kb
  1408 (units kilobytes)

Или просто прочитать файл buffer_total_size_kb

  # cat buffer_total_size_kb 
  5632

Для изменения размера буфера просто записывается (echo) нужное число (в сегментах по 1024 байта).

  # echo 10000 > buffer_size_kb
  # cat buffer_size_kb
  10000 (units kilobytes)

При попытке указать слишком большой размер буферов сработает триггер Out-Of-Memory.

  # echo 1000000000000 > buffer_size_kb
  -bash: echo: write error: Cannot allocate memory
  # cat buffer_size_kb
  85

Буферы per_cpu можно изменять независимо, как показано ниже.

  # echo 10000 > per_cpu/cpu0/buffer_size_kb
  # echo 100 > per_cpu/cpu1/buffer_size_kb

При разных размерах буферов per_cpu файл buffer_size_kb на верхнем уровне просто покажет X.

  # cat buffer_size_kb
  X

В этом случае можно воспользоваться командой

  # cat buffer_total_size_kb 
  12916

Запись в buffer_size_kb верхнего уровня будет сбрасывать буферы всех процессоров к одному размеру.

Мгновенные снимки

Опция ядра CONFIG_TRACER_SNAPSHOT включает возможность создания «моментальных снимков» для всех трассировщиков, кроме трассировщиков задержки. Трассировщики задержки, записывающие максимальное значение (такие как irqsoff или wakeup), не могут использовать эту возможность, поскольку в них уже применяется внутренний механизм snapshot mechanism.

Снимок сохраняет текущий буфер трассировки в конкретный момент времени без остановки отслеживания. Ftrace заменяет текущий буфер запасным и трассировка продолжается в новый (ранее резервный) буфер.

Ниже указаны файлы tracefs (tracing), связанные с этой функцией.

snapshot

используется для записи и считывания моментального снимка. Запись (echo) 1 в этот файл ведет к созданию запасного буфера, записи снимка и последующему его считыванию в формате файла (см. раздел Файловая система). Считывание снимка и трассировка выполняются параллельно. Когда запасной буфер создан, запись (echo) 0 в файл освобождает буфер, а запись други (положительных) значений очищает содержимое снимка.

состояние/ввод

0

1

иное

Не выделен

Ничего

Выделение и переключение

Ничего

Выделен

Освобождение

swap

Очистка

Ниже приведен пример использования моментального снимка.

  # echo 1 > events/sched/enable
  # echo 1 > snapshot
  # cat snapshot
  # tracer: nop
  #
  # entries-in-buffer/entries-written: 71/71   #P:8
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |
            <idle>-0     [005] d...  2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120   prev_state=R ==> next_comm=snapshot-test-2 next_pid=2242 next_prio=120
             sleep-2242  [005] d...  2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_prio=120   prev_state=R ==> next_comm=kworker/5:1 next_pid=60 next_prio=120
  [...]
          <idle>-0     [002] d...  2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2229 next_prio=120  

  # cat trace  
  # tracer: nop
  #
  # entries-in-buffer/entries-written: 77/77   #P:8
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |
            <idle>-0     [007] d...  2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2243 next_prio=120
   snapshot-test-2-2229  [002] d...  2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=2229 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
  [...]

Если попытаться использовать функцию snapshot для одного из трассировщиков задержек, возникнет ошибка.

  # echo wakeup > current_tracer
  # echo 1 > snapshot
  bash: echo: write error: Device or resource busy
  # cat snapshot
  cat: snapshot: Device or resource busy

Экземпляры

В каталоге tracing файловой системы tracefs имеется папка instances, где можно создавать новые каталоги с помощью команды mkdir и удалять их командой rmdir. Создаваемые командой mkdir каталоги сразу будут содержать файлы и другие папки.

  # mkdir instances/foo
  # ls instances/foo
  buffer_size_kb  buffer_total_size_kb  events  free_buffer  per_cpu
  set_event  snapshot  trace  trace_clock  trace_marker  trace_options
  trace_pipe  tracing_on

Как видно из представленного вывода созданный каталог похож на сам каталог tracing. Фактически он отличается лишь тем, что буфер и события не зависят от основного экземпляра и других созданных экземпляров.

Файлы в новом каталоге работают так же, как одноименные файлы каталога tracing, за исключением того, что для нихе применяется независимый новый буфер. Файлы влияют на этот буфер, но не воздействуют на основной буфер (за исключением trace_options). В настоящее время trace_options одинаково влияет на все экземпляры, включая буфер верхнего уровня, но это может измениться в будущих версиях. Т. е. опции могут стать независимыми для каждого экземпляра.

Отмети, что здесь нет ни одного трассировщика функций, а также файлов current_tracer и available_tracers. Это обусловлено тем, что в настоящее буферы могут включать лишь разрешенные для них события.

  # mkdir instances/foo
  # mkdir instances/bar
  # mkdir instances/zoot
  # echo 100000 > buffer_size_kb
  # echo 1000 > instances/foo/buffer_size_kb
  # echo 5000 > instances/bar/per_cpu/cpu1/buffer_size_kb
  # echo function > current_trace
  # echo 1 > instances/foo/events/sched/sched_wakeup/enable
  # echo 1 > instances/foo/events/sched/sched_wakeup_new/enable
  # echo 1 > instances/foo/events/sched/sched_switch/enable
  # echo 1 > instances/bar/events/irq/enable
  # echo 1 > instances/zoot/events/syscalls/enable
  # cat trace_pipe
  CPU:2 [LOST 11745 EVENTS]
              bash-2044  [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
              bash-2044  [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
              bash-2044  [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
              bash-2044  [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
              bash-2044  [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
              bash-2044  [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
              bash-2044  [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
              bash-2044  [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
              bash-2044  [002] d... 10594.481034: __inc_zone_state <-zone_statistics
              bash-2044  [002] d... 10594.481034: __inc_zone_state <-zone_statistics
              bash-2044  [002] .... 10594.481035: arch_dup_task_struct <-copy_process
  [...]
  # cat instances/foo/trace_pipe
              bash-1998  [000] d..4   136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
              bash-1998  [000] dN.4   136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
            <idle>-0     [003] d.h3   136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 target_cpu=003
            <idle>-0     [003] d..3   136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=9 next_prio=120
       rcu_preempt-9     [003] d..3   136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
              bash-1998  [000] d..4   136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
              bash-1998  [000] dN.4   136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
              bash-1998  [000] d..3   136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:1 next_pid=59 next_prio=120
       kworker/0:1-59    [000] d..4   136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 target_cpu=001
       kworker/0:1-59    [000] d..3   136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1998 next_prio=120
  [...]
  # cat instances/bar/trace_pipe
       migration/1-14    [001] d.h3   138.732674: softirq_raise: vec=3 [action=NET_RX]
            <idle>-0     [001] dNh3   138.732725: softirq_raise: vec=3 [action=NET_RX]
              bash-1998  [000] d.h1   138.733101: softirq_raise: vec=1 [action=TIMER]
              bash-1998  [000] d.h1   138.733102: softirq_raise: vec=9 [action=RCU]
              bash-1998  [000] ..s2   138.733105: softirq_entry: vec=1 [action=TIMER]
              bash-1998  [000] ..s2   138.733106: softirq_exit: vec=1 [action=TIMER]
              bash-1998  [000] ..s2   138.733106: softirq_entry: vec=9 [action=RCU]
              bash-1998  [000] ..s2   138.733109: softirq_exit: vec=9 [action=RCU]
              sshd-1995  [001] d.h1   138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
              sshd-1995  [001] d.h1   138.733280: irq_handler_exit: irq=21 ret=unhandled
              sshd-1995  [001] d.h1   138.733281: irq_handler_entry: irq=21 name=eth0
              sshd-1995  [001] d.h1   138.733283: irq_handler_exit: irq=21 ret=handled
  [...]
  # cat instances/zoot/trace
  # tracer: nop
  #
  # entries-in-buffer/entries-written: 18996/18996   #P:4
  #
  #                              _-----=> irqs-off
  #                             / _----=> need-resched
  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            ||| /     delay
  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
  #              | |       |   ||||       |         |
              bash-1998  [000] d...   140.733501: sys_write -> 0x2
              bash-1998  [000] d...   140.733504: sys_dup2(oldfd: a, newfd: 1)
              bash-1998  [000] d...   140.733506: sys_dup2 -> 0x1
              bash-1998  [000] d...   140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
              bash-1998  [000] d...   140.733509: sys_fcntl -> 0x1
              bash-1998  [000] d...   140.733510: sys_close(fd: a)
              bash-1998  [000] d...   140.733510: sys_close -> 0x0
              bash-1998  [000] d...   140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: 8)
              bash-1998  [000] d...   140.733515: sys_rt_sigprocmask -> 0x0
              bash-1998  [000] d...   140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650, sigsetsize: 8)
              bash-1998  [000] d...   140.733516: sys_rt_sigaction -> 0x0

Можно видеть, трассировка в буфере верхнего уровня показывает лишь отслеживание функций, а экземпляр foo показывает пробуждения (wakeup) и переключатели задач.

Для удаления экземпляров просто удалите соответствующие каталоги

  # rmdir instances/foo
  # rmdir instances/bar
  # rmdir instances/zoot

Отметим, что при наличии у процесса открытого в удаляемом экземпляре файла rmdir будетт приводить к отказу с ошибкой EBUSY.

Трассировка стека

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

Существуют инструменты, периодически проверяющие использование стека (обычно с прерываниями). Поскольку ftrace обеспечивает трассировку функций, это позволяет проверять размер стека при каждом вызове функции. Это включается через трассировщик стека. Для включения возможности трассировки стека служит конфигурационный параметр ядра CONFIG_STACK_TRACER.

Для включения трассировки стека записывается 1 в файл /proc/sys/kernel/stack_tracer_enabled

 # echo 1 > /proc/sys/kernel/stack_tracer_enabled

Можно также включить трассировку из командной строки ядра для отслеживания стека в процессе загрузки ядра путем добавления команды stacktrace.

Через несколько минут после активизации трассировки можно посмотреть результаты.

  # cat stack_max_size8
  2928
  # cat stack_trace
          Depth    Size   Location    (18 entries)
          -----    ----   --------
    0)     2928     224   update_sd_lb_stats+0xbc/0x4ac
    1)     2704     160   find_busiest_group+0x31/0x1f1
    2)     2544     256   load_balance+0xd9/0x662
    3)     2288      80   idle_balance+0xbb/0x130
    4)     2208     128   __schedule+0x26e/0x5b9
    5)     2080      16   schedule+0x64/0x66
    6)     2064     128   schedule_timeout+0x34/0xe0
    7)     1936     112   wait_for_common+0x97/0xf1
    8)     1824      16   wait_for_completion+0x1d/0x1f
    9)     1808     128   flush_work+0xfe/0x119
   10)     1680      16   tty_flush_to_ldisc+0x1e/0x20
   11)     1664      48   input_available_p+0x1d/0x5c
   12)     1616      48   n_tty_poll+0x6d/0x134
   13)     1568      64   tty_poll+0x64/0x7f
   14)     1504     880   do_select+0x31e/0x511
   15)      624     400   core_sys_select+0x177/0x216
   16)      224      96   sys_select+0x91/0xb9
   17)      128     128   system_call_fastpath+0x16/0x1b

Отметим, что при использовании опции -mfentry в компиляторе gcc функции будут отслеживаться до того, как они организуют кадр стека. Это означает, что функции конечного уровня (листья — leaf) не будут отслеживаться трассировщиком стека при использовании опции -mfentry. В настоящее время эта опция поддерживается gcc 4.6.0 и выше только на архитектуре x86.


По материалам документации к ядру Linux

Николай Малых

nmalykh@protocols.ru

1Следует отметить, что в некоторых вариантах Linux каталог /sys/kernel/tracing остается пустым, а все упомянутые здесь файлы размещаются только в /sys/kernel/debug/tracing

2В GCC термин trampoline означает метод реализации указателей на вложенные функции. Trampoline — это небольшой фрагмент кода, который создается «на лету» в стеке, когда береься адрес вложенной функции. Trampoline устанавливает статический указатель на привязку (link), который позволяет вложенной функции обращаться к переменным вмещающей ее функции. Указателем на функцию является просто адрес trampoline. Это избавляет от применения «толстых» указателей на функции, передающих адрес кода и статическую ссылку. Однако это вступает в противоречие с тенденцией отказат от исполняемого стека по соображениям безопасности.

3Real time.

4Следует отметить, что, не смотря на одиночный символ >, содержимое файла не переписывается и меняется лишь строка указанной опции.

5Thread Group ID — идентификатор группы потоков.

6Включение FTRACE будет добавлять опции -pg при компиляции ядра

7Начиная с gcc версии 4.6 для процессоров x86 можно добавить опцию -mfentry, которая будет вызывать __fentry__ взамен mcount до создания кадра стека.

8Эта команда показывает не максимальный размер стека, а его максимальное использование к текущему моменту. Для просмотра максимального размера стека, установленного в ядре, служит команда ulimit -s.

Please follow and like us:
error
Запись опубликована в рубрике Linux. Добавьте в закладки постоянную ссылку.

Добавить комментарий